Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Plugin Agent starts a new task even when the previous task is still running. #43

Closed
d200201123 opened this issue Mar 19, 2019 · 5 comments

Comments

Projects
None yet
2 participants
@d200201123
Copy link

commented Mar 19, 2019

Used the below Polling Plugin with a execute_frequency of 30sec

[Core]
Name = Grpc Plugin
Module = /home/panoptes/package/lib/python2.7/site-packages/yahoo_panoptes/plugins/polling/jti/plugin_polling_device_interface_metrics_grpc.py

[Documentation]
Author = Oath, Inc.
Version = 0.1
Website = https://github.com/yahoo/panoptes
Description = This plugin can poll any device supporting IF-MIB for interface metrics.

[main]
execute_frequency = 30
resource_filter = resource_class = "network" AND resource_subclass = "router"

[grpc]
rpc = subscribe
sensor = /interfaces/

[enrichment]
preload = self:interface

The script run as part of the plugin will establish a Grpc connection to the device and fetch Telemetry data.
We continuously poll for the data as part of the script without returning any value ensuring the job will not exit.

The assumption is after 30sec , agent must not start the new task as there is no change in the configuration but we see its starting

As per the below logs we see that process 16135 is still running when the next process 16139 is started.

polling_plugins.log(Snipped data)

[2019-03-19 11:45:54,8] [[SCRIPTNAME]] [grpcsubscribe():507] [PID:16135 TID:139767172859712] /home/panoptes/package/lib/python2.7/site-packages/yahoo_panoptes/plugins/polling/jti
[2019-03-19 11:45:54,8] [[SCRIPTNAME]] [grpcsubscribe():514] [PID:16135 TID:139767172859712] 16058
[2019-03-19 11:45:54,8] [[SCRIPTNAME]] [grpcsubscribe():524] [PID:16135 TID:139767172859712] ------LOCK NOT PRESENT-------
[2019-03-19 11:45:54,8] [[SCRIPTNAME]] [grpcsubscribe():506] [PID:16135 TID:139767172859712] ------LOCK CHECK START-------
[2019-03-19 11:45:54,8] [[SCRIPTNAME]] [grpcsubscribe():526] [PID:16135 TID:139767172859712] ------LOCK CHECK START-------
[2019-03-19 11:45:54,8] [[SCRIPTNAME]] [grpcsubscribe():530] [PID:16135 TID:139767172859712] ------GRPC connection done-------
[2019-03-19 11:45:55,3] [[SCRIPTNAME]] [grpcsubscribe():536] [PID:16135 TID:139767172859712] response { subscription_id: 1 } path_list { path: "/interfaces/" max_silent_interval: 1 sample_frequency: 10000 } 
[2019-03-19 11:45:55,3] [[SCRIPTNAME]] [grpcsubscribe():538] [PID:16135 TID:139767172859712] ------METADATA parse done-------
[2019-03-19 11:45:55,3] [[SCRIPTNAME]] [grpcsubscribe():542] [PID:16135 TID:139767172859712] ------PROTOBUF MERGE done-------
[2019-03-19 11:45:55,3] [[SCRIPTNAME]] [grpcsubscribe():546] [PID:16135 TID:139767172859712] 1
[2019-03-19 11:45:55,3] [[SCRIPTNAME]] [grpcsubscribe():547] [PID:16135 TID:139767172859712] ------GRPC SUBID done-------
[2019-03-19 11:45:57,5] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:45:57,5] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:45:57,5] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:45:58,0] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:45:58,1] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:45:58,2] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:45:58,2] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:46:08,0] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:46:08,1] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:46:08,2] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:46:08,4] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:46:08,4] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:46:08,4] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:46:08,4] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:46:18,0] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:46:29,8] [[SCRIPTNAME]] [grpcsubscribe():506] [PID:16139 TID:139767172859712] ------LOCK CHECK START-------
[2019-03-19 11:46:29,8] [[SCRIPTNAME]] [grpcsubscribe():507] [PID:16139 TID:139767172859712] /home/panoptes/package/lib/python2.7/site-packages/yahoo_panoptes/plugins/polling/jti
[2019-03-19 11:46:29,8] [[SCRIPTNAME]] [grpcsubscribe():514] [PID:16139 TID:139767172859712] LOCKING PID : 16135
[2019-03-19 11:46:29,8] [[SCRIPTNAME]] [grpcsubscribe():518] [PID:16139 TID:139767172859712] ------LOCK ALREADY PRESENT-------
[2019-03-19 11:46:30,2] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:46:30,2] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c
[2019-03-19 11:46:30,2] [[SCRIPTNAME]] [grpcsubscribe():561] [PID:16135 TID:139767172859712] Receiving data from train-c

polling_plugin_agent.log

[2019-03-19 11:45:54,690] [INFO] [context] [_get_redis_connection():257] [PID:16135 TID:139767172859712] Attempting to connect to Redis for group "default", shard "0", url "redis://localhost:6379/0"
[2019-03-19 11:45:54,690] [INFO] [context] [_get_redis_connection():267] [PID:16135 TID:139767172859712] Successfully connected to Redis for group "default", shard "0", url "redis://localhost:6379/0"
[2019-03-19 11:45:54,691] [INFO] [context] [_get_kv_store():284] [PID:16135 TID:139767172859712] Attempting to connect to KV Store "PanoptesPollingPluginAgentKeyValueStore"
[2019-03-19 11:45:54,691] [INFO] [context] [_get_kv_store():290] [PID:16135 TID:139767172859712] Connected to KV Store "PanoptesPollingPluginAgentKeyValueStore": <yahoo_panoptes.polling.polling_plugin_agent.PanoptesPollingPluginAgentKeyValueStore object at 0x7f1e0e6ff390>
[2019-03-19 11:45:54,691] [INFO] [context] [_get_kv_store():284] [PID:16135 TID:139767172859712] Attempting to connect to KV Store "PanoptesPollingPluginKeyValueStore"
[2019-03-19 11:45:54,691] [INFO] [context] [_get_kv_store():290] [PID:16135 TID:139767172859712] Connected to KV Store "PanoptesPollingPluginKeyValueStore": <yahoo_panoptes.polling.polling_plugin_agent.PanoptesPollingPluginKeyValueStore object at 0x7f1e0e6ff3d0>
[2019-03-19 11:45:54,691] [INFO] [context] [_get_kv_store():284] [PID:16135 TID:139767172859712] Attempting to connect to KV Store "PanoptesSecretsStore"
[2019-03-19 11:45:54,691] [INFO] [context] [_get_kv_store():290] [PID:16135 TID:139767172859712] Connected to KV Store "PanoptesSecretsStore": <yahoo_panoptes.framework.utilities.secrets.PanoptesSecretsStore object at 0x7f1e0e6ff350>
[2019-03-19 11:45:54,691] [INFO] [context] [_get_kv_store():284] [PID:16135 TID:139767172859712] Attempting to connect to KV Store "PanoptesResourcesKeyValueStore"
[2019-03-19 11:45:54,691] [INFO] [context] [_get_kv_store():290] [PID:16135 TID:139767172859712] Connected to KV Store "PanoptesResourcesKeyValueStore": <yahoo_panoptes.framework.resources.PanoptesResourcesKeyValueStore object at 0x7f1e0e6ff410>
[2019-03-19 11:45:54,691] [INFO] [context] [_get_kv_store():284] [PID:16135 TID:139767172859712] Attempting to connect to KV Store "PanoptesMetricsKeyValueStore"
[2019-03-19 11:45:54,692] [INFO] [context] [_get_kv_store():290] [PID:16135 TID:139767172859712] Connected to KV Store "PanoptesMetricsKeyValueStore": <yahoo_panoptes.polling.polling_plugin_agent.PanoptesMetricsKeyValueStore object at 0x7f1e0e6ff450>
[2019-03-19 11:45:54,692] [INFO] [context] [_get_kafka_client():308] [PID:16135 TID:139767172859712] Attempting to connect Kafka
[2019-03-19 11:45:54,701] [INFO] [context] [_get_kafka_client():319] [PID:16135 TID:139767172859712] Successfully connected to Kafka brokers: {0: BrokerMetadata(nodeId=0, host=u'localhost.localdomain', port=9092, rack=None)}
[2019-03-19 11:45:54,701] [INFO] [context] [_get_message_producer():336] [PID:16135 TID:139767172859712] Attempting to connect to message bus
[2019-03-19 11:45:54,703] [INFO] [context] [_get_message_producer():341] [PID:16135 TID:139767172859712] Connected to message bus: <yahoo_panoptes.framework.utilities.message_queue.PanoptesMessageQueueProducer object at 0x7f1e0e6ff590>
[2019-03-19 11:45:54,704] [INFO] [context] [_get_zookeeper_client():358] [PID:16135 TID:139767172859712] Attempting to connect to Zookeeper with servers: localhost:2181
[2019-03-19 11:45:54,713] [INFO] [context] [_get_zookeeper_client():364] [PID:16135 TID:139767172859712] Successfully connected to Zookeeper: <kazoo.client.KazooClient object at 0x7f1e0e6ff810>
[2019-03-19 11:45:54,719] [INFO] [runner] [execute_plugin():119] [PID:16135 TID:139767172859712] Attempting to execute plugin "Grpc Plugin"
[2019-03-19 11:45:54,849] [INFO] [runner] [execute_plugin():129] [PID:16135 TID:139767172859712] ----------------------------
[2019-03-19 11:45:54,857] [INFO] [lock] [_get_lock():70] [PID:16135 TID:139767172859712] Creating lock for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/polling//plugins/lock//Grpc_Plugin/d714ba828e6af8ba044f678a5bf76dc5, timeout=5, retries=1, identifier=4d318d33-d90e-42ff-b4bf-2edd4a621bb5_plugin_ubuntu-14_16135
[2019-03-19 11:45:54,860] [INFO] [lock] [_get_lock():81] [PID:16135 TID:139767172859712] Trying to acquire lock for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/polling//plugins/lock//Grpc_Plugin/d714ba828e6af8ba044f678a5bf76dc5, timeout=5, retries=1, identifier=4d318d33-d90e-42ff-b4bf-2edd4a621bb5_plugin_ubuntu-14_16135. Other contenders: []
[2019-03-19 11:45:54,866] [INFO] [lock] [_get_lock():96] [PID:16135 TID:139767172859712] Lock acquired for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/polling//plugins/lock//Grpc_Plugin/d714ba828e6af8ba044f678a5bf76dc5, timeout=5, retries=1, identifier=4d318d33-d90e-42ff-b4bf-2edd4a621bb5_plugin_ubuntu-14_16135. Other contenders: [u'4d318d33-d90e-42ff-b4bf-2edd4a621bb5_plugin_ubuntu-14_16135']
[2019-03-19 11:45:54,849] [INFO] [runner] [execute_plugin():130] [PID:16135 TID:139767172859712] PanoptesPluginInfo: Normalized name: Grpc_Plugin, Config file: /home/panoptes/plugins/polling/plugin_polling_device_interface_metrics_grpc.panoptes-plugin, Panoptes context: [PanoptesContext: KV Stores: [PanoptesPollingPluginAgentKeyValueStore,PanoptesMetricsKeyValueStore,PanoptesResourcesKeyValueStore,PanoptesPollingPluginKeyValueStore,PanoptesSecretsStore], Config: ConfigObj({'main': {'sites': ['local'], 'plugins_extension': 'panoptes-plugin', 'plugins_skew': 1}, 'log': {'config_file': '/home/panoptes/conf/logging.ini', 'rate': 1000, 'per': 1, 'burst': 10000}, 'redis': {'default': {'namespace': 'panoptes', 'shards': {'0': {'host': 'localhost', 'port': 6379, 'db': 0, 'password': ''}}}}, 'kafka': {'topic_name_delimiter': '-', 'topic_key_delimiter': ':', 'brokers': {'broker1': {'host': 'localhost', 'port': 9092}}, 'topics': {'metrics': {'raw_topic_name_suffix': 'metrics', 'transformed_topic_name_suffix': 'processed'}}}, 'zookeeper': {'connection_timeout': 30, 'servers': {'server1': {'host': 'localhost', 'port': 2181}}}, 'discovery': {'plugins_paths': ['/home/panoptes/plugins/discovery'], 'plugin_scan_interval': 60, 'celerybeat_max_loop_interval': 5}, 'polling': {'plugins_paths': ['/home/panoptes/plugins/polling'], 'plugin_scan_interval': 90, 'celerybeat_max_loop_interval': 90}, 'enrichment': {'plugins_paths': ['/home/panoptes/plugins/enrichment'], 'plugin_scan_interval': 60, 'celerybeat_max_loop_interval': 5}, 'snmp': {'connection_factory_module': 'yahoo_panoptes.framework.utilities.snmp.connection', 'connection_factory_class': 'PanoptesSNMPConnectionFactory', 'community': '**', 'timeout': 5, 'retries': 1, 'non_repeaters': 0, 'max_repetitions': 25, 'port': 161, 'proxy_port': 10161, 'community_string_key': 'snmp_community_string'}, 'grpc': {'connection_factory_module': 'yahoo_panoptes.framework.utilities.grpc.connection', 'connection_factory_class': 'PanoptesGRPCConnectionFactory', 'timeout': 5, 'retries': 1, 'non_repeaters': 0, 'max_repetitions': 25, 'port': 32767}}), Redis pool set: False, Message producer set: False, Kafka client set: True, Zookeeper client set: False], KV store class: PanoptesPollingPluginAgentKeyValueStore, Last executed timestamp: 0, Last executed key: plugin_metadata:Grpc_Plugin:d714ba828e6af8ba044f678a5bf76dc5:last_executed, Last results timestamp: 0, Last results key: plugin_metadata:Grpc_Plugin:d714ba828e6af8ba044f678a5bf76dc5:last_results, Data: Data object passed, Lock: Lock is set
[2019-03-19 11:45:54,869] [ERROR] [enrichment] [_preload_data():598] [PID:16135 TID:139767172859712] No enrichment data found on KV store for plugin Grpc Plugin resource train-c namespace interface using key train-c:interface
[2019-03-19 11:45:54,870] [INFO] [runner] [info():74] [PID:16135 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] Attempting to get lock for plugin "Grpc Plugin"
[2019-03-19 11:45:54,870] [INFO] [runner] [info():74] [PID:16135 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] -----
[2019-03-19 11:45:54,870] [INFO] [runner] [info():74] [PID:16135 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/polling//plugins/lock//Grpc_Plugin/d714ba828e6af8ba044f678a5bf76dc5, timeout=5, retries=1, identifier=4d318d33-d90e-42ff-b4bf-2edd4a621bb5_plugin_ubuntu-14_16135
[2019-03-19 11:45:54,870] [INFO] [runner] [info():74] [PID:16135 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] True
[2019-03-19 11:45:54,870] [INFO] [runner] [info():74] [PID:16135 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] Acquired lock
[2019-03-19 11:45:54,870] [INFO] [runner] [info():74] [PID:16135 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] Going to run plugin "Grpc Plugin", version "0.1", which last executed at 0 (UTC) (1552976154 seconds ago) and last produced results at 0 (UTC) (1552976154 seconds ago), module mtime 0 (UTC), config mtime 1552926812 (UTC)
[2019-03-19 11:46:24,670] [INFO] [context] [_get_redis_connection():257] [PID:16139 TID:139767172859712] Attempting to connect to Redis for group "default", shard "0", url "redis://localhost:6379/0"
[2019-03-19 11:46:24,671] [INFO] [context] [_get_redis_connection():267] [PID:16139 TID:139767172859712] Successfully connected to Redis for group "default", shard "0", url "redis://localhost:6379/0"
[2019-03-19 11:46:24,671] [INFO] [context] [_get_kv_store():284] [PID:16139 TID:139767172859712] Attempting to connect to KV Store "PanoptesPollingPluginAgentKeyValueStore"
[2019-03-19 11:46:24,671] [INFO] [context] [_get_kv_store():290] [PID:16139 TID:139767172859712] Connected to KV Store "PanoptesPollingPluginAgentKeyValueStore": <yahoo_panoptes.polling.polling_plugin_agent.PanoptesPollingPluginAgentKeyValueStore object at 0x7f1e0e6ff790>
[2019-03-19 11:46:24,671] [INFO] [context] [_get_kv_store():284] [PID:16139 TID:139767172859712] Attempting to connect to KV Store "PanoptesPollingPluginKeyValueStore"
[2019-03-19 11:46:24,671] [INFO] [context] [_get_kv_store():290] [PID:16139 TID:139767172859712] Connected to KV Store "PanoptesPollingPluginKeyValueStore": <yahoo_panoptes.polling.polling_plugin_agent.PanoptesPollingPluginKeyValueStore object at 0x7f1e0e6ff7d0>
[2019-03-19 11:46:24,672] [INFO] [context] [_get_kv_store():284] [PID:16139 TID:139767172859712] Attempting to connect to KV Store "PanoptesSecretsStore"
[2019-03-19 11:46:24,672] [INFO] [context] [_get_kv_store():290] [PID:16139 TID:139767172859712] Connected to KV Store "PanoptesSecretsStore": <yahoo_panoptes.framework.utilities.secrets.PanoptesSecretsStore object at 0x7f1e0e6ff750>
[2019-03-19 11:46:24,672] [INFO] [context] [_get_kv_store():284] [PID:16139 TID:139767172859712] Attempting to connect to KV Store "PanoptesResourcesKeyValueStore"
[2019-03-19 11:46:24,672] [INFO] [context] [_get_kv_store():290] [PID:16139 TID:139767172859712] Connected to KV Store "PanoptesResourcesKeyValueStore": <yahoo_panoptes.framework.resources.PanoptesResourcesKeyValueStore object at 0x7f1e0e6ff810>
[2019-03-19 11:46:24,672] [INFO] [context] [_get_kv_store():284] [PID:16139 TID:139767172859712] Attempting to connect to KV Store "PanoptesMetricsKeyValueStore"
[2019-03-19 11:46:24,672] [INFO] [context] [_get_kv_store():290] [PID:16139 TID:139767172859712] Connected to KV Store "PanoptesMetricsKeyValueStore": <yahoo_panoptes.polling.polling_plugin_agent.PanoptesMetricsKeyValueStore object at 0x7f1e0e6ff850>
[2019-03-19 11:46:24,672] [INFO] [context] [_get_kafka_client():308] [PID:16139 TID:139767172859712] Attempting to connect Kafka
[2019-03-19 11:46:24,681] [INFO] [context] [_get_kafka_client():319] [PID:16139 TID:139767172859712] Successfully connected to Kafka brokers: {0: BrokerMetadata(nodeId=0, host=u'localhost.localdomain', port=9092, rack=None)}
[2019-03-19 11:46:24,681] [INFO] [context] [_get_message_producer():336] [PID:16139 TID:139767172859712] Attempting to connect to message bus
[2019-03-19 11:46:24,682] [INFO] [context] [_get_message_producer():341] [PID:16139 TID:139767172859712] Connected to message bus: <yahoo_panoptes.framework.utilities.message_queue.PanoptesMessageQueueProducer object at 0x7f1e0e6ff990>
[2019-03-19 11:46:24,683] [INFO] [context] [_get_zookeeper_client():358] [PID:16139 TID:139767172859712] Attempting to connect to Zookeeper with servers: localhost:2181
[2019-03-19 11:46:24,696] [INFO] [context] [_get_zookeeper_client():364] [PID:16139 TID:139767172859712] Successfully connected to Zookeeper: <kazoo.client.KazooClient object at 0x7f1e0e6ffc10>
[2019-03-19 11:46:24,702] [INFO] [runner] [execute_plugin():119] [PID:16139 TID:139767172859712] Attempting to execute plugin "Grpc Plugin"
[2019-03-19 11:46:24,842] [INFO] [runner] [execute_plugin():129] [PID:16139 TID:139767172859712] ----------------------------
[2019-03-19 11:46:24,855] [INFO] [lock] [_get_lock():70] [PID:16139 TID:139767172859712] Creating lock for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/polling//plugins/lock//Grpc_Plugin/d714ba828e6af8ba044f678a5bf76dc5, timeout=5, retries=1, identifier=62b522d9-613e-465f-b1c2-db82a29196b1_plugin_ubuntu-14_16139
[2019-03-19 11:46:24,858] [INFO] [lock] [_get_lock():81] [PID:16139 TID:139767172859712] Trying to acquire lock for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/polling//plugins/lock//Grpc_Plugin/d714ba828e6af8ba044f678a5bf76dc5, timeout=5, retries=1, identifier=62b522d9-613e-465f-b1c2-db82a29196b1_plugin_ubuntu-14_16139. Other contenders: [u'4d318d33-d90e-42ff-b4bf-2edd4a621bb5_plugin_ubuntu-14_16135']
[2019-03-19 11:46:29,864] [INFO] [lock] [_get_lock():86] [PID:16139 TID:139767172859712] Timed out after 5 seconds trying to acquire lock for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/polling//plugins/lock//Grpc_Plugin/d714ba828e6af8ba044f678a5bf76dc5, timeout=5, retries=1, identifier=62b522d9-613e-465f-b1c2-db82a29196b1_plugin_ubuntu-14_16139
[2019-03-19 11:46:29,865] [WARNING] [lock] [_get_lock():94] [PID:16139 TID:139767172859712] Failed to acquire lock for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/polling//plugins/lock//Grpc_Plugin/d714ba828e6af8ba044f678a5bf76dc5, timeout=5, retries=1, identifier=62b522d9-613e-465f-b1c2-db82a29196b1_plugin_ubuntu-14_16139 after 1 tries
[2019-03-19 11:46:24,842] [INFO] [runner] [execute_plugin():130] [PID:16139 TID:139767172859712] PanoptesPluginInfo: Normalized name: Grpc_Plugin, Config file: /home/panoptes/plugins/polling/plugin_polling_device_interface_metrics_grpc.panoptes-plugin, Panoptes context: [PanoptesContext: KV Stores: [PanoptesPollingPluginAgentKeyValueStore,PanoptesMetricsKeyValueStore,PanoptesResourcesKeyValueStore,PanoptesPollingPluginKeyValueStore,PanoptesSecretsStore], Config: ConfigObj({'main': {'sites': ['local'], 'plugins_extension': 'panoptes-plugin', 'plugins_skew': 1}, 'log': {'config_file': '/home/panoptes/conf/logging.ini', 'rate': 1000, 'per': 1, 'burst': 10000}, 'redis': {'default': {'namespace': 'panoptes', 'shards': {'0': {'host': 'localhost', 'port': 6379, 'db': 0, 'password': ''}}}}, 'kafka': {'topic_name_delimiter': '-', 'topic_key_delimiter': ':', 'brokers': {'broker1': {'host': 'localhost', 'port': 9092}}, 'topics': {'metrics': {'raw_topic_name_suffix': 'metrics', 'transformed_topic_name_suffix': 'processed'}}}, 'zookeeper': {'connection_timeout': 30, 'servers': {'server1': {'host': 'localhost', 'port': 2181}}}, 'discovery': {'plugins_paths': ['/home/panoptes/plugins/discovery'], 'plugin_scan_interval': 60, 'celerybeat_max_loop_interval': 5}, 'polling': {'plugins_paths': ['/home/panoptes/plugins/polling'], 'plugin_scan_interval': 90, 'celerybeat_max_loop_interval': 90}, 'enrichment': {'plugins_paths': ['/home/panoptes/plugins/enrichment'], 'plugin_scan_interval': 60, 'celerybeat_max_loop_interval': 5}, 'snmp': {'connection_factory_module': 'yahoo_panoptes.framework.utilities.snmp.connection', 'connection_factory_class': 'PanoptesSNMPConnectionFactory', 'community': '**', 'timeout': 5, 'retries': 1, 'non_repeaters': 0, 'max_repetitions': 25, 'port': 161, 'proxy_port': 10161, 'community_string_key': 'snmp_community_string'}, 'grpc': {'connection_factory_module': 'yahoo_panoptes.framework.utilities.grpc.connection', 'connection_factory_class': 'PanoptesGRPCConnectionFactory', 'timeout': 5, 'retries': 1, 'non_repeaters': 0, 'max_repetitions': 25, 'port': 32767}}), Redis pool set: False, Message producer set: False, Kafka client set: True, Zookeeper client set: False], KV store class: PanoptesPollingPluginAgentKeyValueStore, Last executed timestamp: 0, Last executed key: plugin_metadata:Grpc_Plugin:d714ba828e6af8ba044f678a5bf76dc5:last_executed, Last results timestamp: 0, Last results key: plugin_metadata:Grpc_Plugin:d714ba828e6af8ba044f678a5bf76dc5:last_results, Data: Data object passed, Lock: Lock is set
[2019-03-19 11:46:29,871] [ERROR] [enrichment] [_preload_data():598] [PID:16139 TID:139767172859712] No enrichment data found on KV store for plugin Grpc Plugin resource train-c namespace interface using key train-c:interface
[2019-03-19 11:46:29,871] [INFO] [runner] [info():74] [PID:16139 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] Attempting to get lock for plugin "Grpc Plugin"
[2019-03-19 11:46:29,871] [INFO] [runner] [info():74] [PID:16139 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] -----
[2019-03-19 11:46:29,871] [INFO] [runner] [info():74] [PID:16139 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/polling//plugins/lock//Grpc_Plugin/d714ba828e6af8ba044f678a5bf76dc5, timeout=5, retries=1, identifier=62b522d9-613e-465f-b1c2-db82a29196b1_plugin_ubuntu-14_16139
[2019-03-19 11:46:29,871] [INFO] [runner] [info():74] [PID:16139 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] False
[2019-03-19 11:46:29,871] [INFO] [runner] [info():74] [PID:16139 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] Acquired lock
[2019-03-19 11:46:29,872] [INFO] [runner] [info():74] [PID:16139 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] Going to run plugin "Grpc Plugin", version "0.1", which last executed at 0 (UTC) (1552976189 seconds ago) and last produced results at 0 (UTC) (1552976189 seconds ago), module mtime 0 (UTC), config mtime 1552926812 (UTC)
[2019-03-19 11:46:29,873] [INFO] [runner] [info():74] [PID:16139 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] Ran in 0.00 seconds
[2019-03-19 11:46:29,873] [INFO] [runner] [info():74] [PID:16139 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] Released lock
[2019-03-19 11:46:29,873] [WARNING] [runner] [warn():77] [PID:16139 TID:139767172859712] [Grpc Plugin:d714ba828e6af8ba044f678a5bf76dc5] [plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163] Plugin did not return any results

polling_plugin_agent_celery_worker_001.log

[2019-03-19 11:45:36,693: INFO/MainProcess] celery@polling_plugin_agent_001.ubuntu-14 ready.
[2019-03-19 11:45:36,842: INFO/MainProcess] Received task: yahoo_panoptes.polling.polling_plugin_agent.polling_plugin_task[5fe22ee0-6dbe-42c4-8c3b-febc1e8df41a]   expires:[2019-03-19 06:11:14.022268+00:00]
[2019-03-19 11:45:36,843: INFO/MainProcess] Discarding revoked task: yahoo_panoptes.polling.polling_plugin_agent.polling_plugin_task[5fe22ee0-6dbe-42c4-8c3b-febc1e8df41a]
[2019-03-19 11:45:36,947: DEBUG/MainProcess] celery@discovery_plugin_agent.ubuntu-14 joined the party
[2019-03-19 11:45:54,629: INFO/MainProcess] Received task: yahoo_panoptes.polling.polling_plugin_agent.polling_plugin_task[1e7799cd-52ca-4654-88e2-9cf5b77d1168]   expires:[2019-03-19 06:16:54.616635+00:00]
[2019-03-19 11:45:54,629: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7f1e0ec22de8> (args:(u'yahoo_panoptes.polling.polling_plugin_agent.polling_plugin_task', u'1e7799cd-52ca-4654-88e2-9cf5b77d1168', {u'origin': u'gen16117@ubuntu-14', u'lang': u'py', u'task': u'yahoo_panoptes.polling.polling_plugin_agent.polling_plugin_task', u'group': None, u'root_id': u'1e7799cd-52ca-4654-88e2-9cf5b77d1168', u'delivery_info': {u'priority': 0, u'redelivered': None, u'routing_key': u'polling_plugin_agent', u'exchange': u''}, u'expires': u'2019-03-19T06:16:54.616635+00:00', u'correlation_id': u'1e7799cd-52ca-4654-88e2-9cf5b77d1168', u'retries': 0, u'timelimit': [38.0, None], u'argsrepr': u"('Grpc Plugin', 'plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163')", u'eta': None, u'parent_id': None, u'reply_to': u'f7c96741-fdd3-3dce-a6f1-43f1b3db7f1d', u'shadow': None, u'id': u'1e7799cd-52ca-4654-88e2-9cf5b77d1168', u'kwargsrepr': u'{}'}, '[["Grpc Plugin",... kwargs:{})
[2019-03-19 11:45:54,634: WARNING/ForkPoolWorker-4] [2019-03-19 11:45:54,633: INFO/ForkPoolWorker-4] Attempting to get Panoptes Configuration
[2019-03-19 11:45:54,633: INFO/ForkPoolWorker-4] Attempting to get Panoptes Configuration
[2019-03-19 11:45:54,635: WARNING/ForkPoolWorker-4] [2019-03-19 11:45:54,635: INFO/ForkPoolWorker-4] Using configuration file: /home/panoptes/conf/panoptes.ini
[2019-03-19 11:45:54,635: INFO/ForkPoolWorker-4] Using configuration file: /home/panoptes/conf/panoptes.ini
[2019-03-19 11:45:54,645: DEBUG/MainProcess] Task accepted: yahoo_panoptes.polling.polling_plugin_agent.polling_plugin_task[1e7799cd-52ca-4654-88e2-9cf5b77d1168] pid:16135
[2019-03-19 11:45:54,647: WARNING/ForkPoolWorker-4] [2019-03-19 11:45:54,647: INFO/ForkPoolWorker-4] Logging configuration file: /home/panoptes/conf/logging.ini
[2019-03-19 11:45:54,647: INFO/ForkPoolWorker-4] Logging configuration file: /home/panoptes/conf/logging.ini
[2019-03-19 11:46:24,613: INFO/MainProcess] Received task: yahoo_panoptes.polling.polling_plugin_agent.polling_plugin_task[816c5686-2c79-4541-81df-6ce68d289dfb]   expires:[2019-03-19 06:17:24.609926+00:00]
[2019-03-19 11:46:24,614: DEBUG/MainProcess] TaskPool: Apply <function _fast_trace_task at 0x7f1e0ec22de8> (args:(u'yahoo_panoptes.polling.polling_plugin_agent.polling_plugin_task', u'816c5686-2c79-4541-81df-6ce68d289dfb', {u'origin': u'gen16117@ubuntu-14', u'lang': u'py', u'task': u'yahoo_panoptes.polling.polling_plugin_agent.polling_plugin_task', u'group': None, u'root_id': u'816c5686-2c79-4541-81df-6ce68d289dfb', u'delivery_info': {u'priority': 0, u'redelivered': None, u'routing_key': u'polling_plugin_agent', u'exchange': u''}, u'expires': u'2019-03-19T06:17:24.609926+00:00', u'correlation_id': u'816c5686-2c79-4541-81df-6ce68d289dfb', u'retries': 0, u'timelimit': [38.0, None], u'argsrepr': u"('Grpc Plugin', 'plugin|plugin_discovery_from_json_file|site|local|class|network|subclass|router|type|juniper|id|train-c|endpoint|10.221.130.163')", u'eta': None, u'parent_id': None, u'reply_to': u'f7c96741-fdd3-3dce-a6f1-43f1b3db7f1d', u'shadow': None, u'id': u'816c5686-2c79-4541-81df-6ce68d289dfb', u'kwargsrepr': u'{}'}, '[["Grpc Plugin",... kwargs:{})
[2019-03-19 11:46:24,621: WARNING/ForkPoolWorker-8] [2019-03-19 11:46:24,621: INFO/ForkPoolWorker-8] Attempting to get Panoptes Configuration
[2019-03-19 11:46:24,621: INFO/ForkPoolWorker-8] Attempting to get Panoptes Configuration
[2019-03-19 11:46:24,622: WARNING/ForkPoolWorker-8] [2019-03-19 11:46:24,622: INFO/ForkPoolWorker-8] Using configuration file: /home/panoptes/conf/panoptes.ini
[2019-03-19 11:46:24,622: INFO/ForkPoolWorker-8] Using configuration file: /home/panoptes/conf/panoptes.ini
[2019-03-19 11:46:24,632: DEBUG/MainProcess] Task accepted: yahoo_panoptes.polling.polling_plugin_agent.polling_plugin_task[816c5686-2c79-4541-81df-6ce68d289dfb] pid:16139
[2019-03-19 11:46:24,634: WARNING/ForkPoolWorker-8] [2019-03-19 11:46:24,634: INFO/ForkPoolWorker-8] Logging configuration file: /home/panoptes/conf/logging.ini
[2019-03-19 11:46:24,634: INFO/ForkPoolWorker-8] Logging configuration file: /home/panoptes/conf/logging.ini
@varunvarma

This comment has been minimized.

Copy link
Contributor

commented Mar 26, 2019

Hey Sarath,

Thank you for reporting this issue. We have been able to reproduce this and the fix would be to change the following line:

to

if lock is None or not lock.locked:

Will test internally and raise a PR to fix this.

Regards,
-Varun

@d200201123

This comment has been minimized.

Copy link
Author

commented Mar 29, 2019

Hi Varun,

I have made the changes you have suggested(runner.py)

But I see issue when discovery agent is running
The Agent is not able to aquire lock ()

panoptes@ubuntu-14:~/log/discovery/agent$ head -n 150 discovery_plugin_agent.log    

[2019-03-29 10:22:39,538] [INFO] [context] [_get_redis_connection():257] [PID:23870 TID:140611731175232] Attempting to connect to Redis for group "default", shard "0", url "redis://localhost:6379/0"
[2019-03-29 10:22:39,539] [INFO] [context] [_get_redis_connection():267] [PID:23870 TID:140611731175232] Successfully connected to Redis for group "default", shard "0", url "redis://localhost:6379/0"
[2019-03-29 10:22:39,539] [INFO] [context] [_get_kv_store():284] [PID:23870 TID:140611731175232] Attempting to connect to KV Store "PanoptesDiscoveryPluginAgentKeyValueStore"
[2019-03-29 10:22:39,539] [INFO] [context] [_get_kv_store():290] [PID:23870 TID:140611731175232] Connected to KV Store "PanoptesDiscoveryPluginAgentKeyValueStore": <yahoo_panoptes.discovery.discovery_plugin_agent.PanoptesDiscoveryPluginAgentKeyValueStore object at 0x7fe2b20f5fd0>
[2019-03-29 10:22:39,539] [INFO] [context] [_get_kv_store():284] [PID:23870 TID:140611731175232] Attempting to connect to KV Store "PanoptesDiscoveryPluginKeyValueStore"
[2019-03-29 10:22:39,539] [INFO] [context] [_get_kv_store():290] [PID:23870 TID:140611731175232] Connected to KV Store "PanoptesDiscoveryPluginKeyValueStore": <yahoo_panoptes.discovery.discovery_plugin_agent.PanoptesDiscoveryPluginKeyValueStore object at 0x7fe2b20ff050>
[2019-03-29 10:22:39,539] [INFO] [context] [_get_kv_store():284] [PID:23870 TID:140611731175232] Attempting to connect to KV Store "PanoptesSecretsStore"
[2019-03-29 10:22:39,539] [INFO] [context] [_get_kv_store():290] [PID:23870 TID:140611731175232] Connected to KV Store "PanoptesSecretsStore": <yahoo_panoptes.framework.utilities.secrets.PanoptesSecretsStore object at 0x7fe2b20ff090>
[2019-03-29 10:22:39,539] [INFO] [context] [_get_kafka_client():308] [PID:23870 TID:140611731175232] Attempting to connect Kafka
[2019-03-29 10:22:39,557] [INFO] [context] [_get_kafka_client():319] [PID:23870 TID:140611731175232] Successfully connected to Kafka brokers: {0: BrokerMetadata(nodeId=0, host=u'localhost.localdomain', port=9092, rack=None)}
[2019-03-29 10:22:39,557] [INFO] [context] [_get_message_producer():336] [PID:23870 TID:140611731175232] Attempting to connect to message bus
[2019-03-29 10:22:39,559] [INFO] [context] [_get_message_producer():341] [PID:23870 TID:140611731175232] Connected to message bus: <yahoo_panoptes.framework.utilities.message_queue.PanoptesMessageQueueProducer object at 0x7fe2b20ff1d0>
[2019-03-29 10:22:39,559] [INFO] [context] [_get_zookeeper_client():358] [PID:23870 TID:140611731175232] Attempting to connect to Zookeeper with servers: localhost:2181
[2019-03-29 10:22:39,580] [INFO] [context] [_get_zookeeper_client():364] [PID:23870 TID:140611731175232] Successfully connected to Zookeeper: <kazoo.client.KazooClient object at 0x7fe2b20ff450>
[2019-03-29 10:22:39,588] [INFO] [runner] [execute_plugin():119] [PID:23870 TID:140611731175232] Attempting to execute plugin "From JSON File Discovery Plugin"
[2019-03-29 10:22:39,594] [INFO] [runner] [execute_plugin():129] [PID:23870 TID:140611731175232] ----------------------------
[2019-03-29 10:22:39,603] [INFO] [lock] [_get_lock():70] [PID:23870 TID:140611731175232] Creating lock for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/discovery//plugins/lock//From_JSON_File_Discovery_Plugin/b5d7e0130618ca9daeec1e9c709fc262, timeout=5, retries=1, identifier=50810e98-3c6a-4ad5-829a-6188f596dc22_plugin_ubuntu-14_23870
[2019-03-29 10:22:39,606] [INFO] [lock] [_get_lock():81] [PID:23870 TID:140611731175232] Trying to acquire lock for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/discovery//plugins/lock//From_JSON_File_Discovery_Plugin/b5d7e0130618ca9daeec1e9c709fc262, timeout=5, retries=1, identifier=50810e98-3c6a-4ad5-829a-6188f596dc22_plugin_ubuntu-14_23870. Other contenders: [u'a2cd4734-3667-4450-90ad-559713289f7c_plugin_ubuntu-14_23850']
[2019-03-29 10:22:45,617] [INFO] [lock] [_get_lock():86] [PID:23870 TID:140611731175232] Timed out after 5 seconds trying to acquire lock for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/discovery//plugins/lock//From_JSON_File_Discovery_Plugin/b5d7e0130618ca9daeec1e9c709fc262, timeout=5, retries=1, identifier=50810e98-3c6a-4ad5-829a-6188f596dc22_plugin_ubuntu-14_23870
[2019-03-29 10:22:45,617] [WARNING] [lock] [_get_lock():94] [PID:23870 TID:140611731175232] Failed to acquire lock for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/discovery//plugins/lock//From_JSON_File_Discovery_Plugin/b5d7e0130618ca9daeec1e9c709fc262, timeout=5, retries=1, identifier=50810e98-3c6a-4ad5-829a-6188f596dc22_plugin_ubuntu-14_23870 after 1 tries
[2019-03-29 10:22:39,594] [INFO] [runner] [execute_plugin():130] [PID:23870 TID:140611731175232] PanoptesPluginInfo: Normalized name: From_JSON_File_Discovery_Plugin, Config file: /home/panoptes/plugins/discovery/plugin_discovery_from_json_file.panoptes-plugin, Panoptes context: [PanoptesContext: KV Stores: [PanoptesDiscoveryPluginAgentKeyValueStore,PanoptesSecretsStore,PanoptesDiscoveryPluginKeyValueStore], Config: ConfigObj({'main': {'sites': ['local'], 'plugins_extension': 'panoptes-plugin', 'plugins_skew': 1}, 'log': {'config_file': '/home/panoptes/conf/logging.ini', 'rate': 1000, 'per': 1, 'burst': 10000}, 'redis': {'default': {'namespace': 'panoptes', 'shards': {'0': {'host': 'localhost', 'port': 6379, 'db': 0, 'password': ''}}}}, 'kafka': {'topic_name_delimiter': '-', 'topic_key_delimiter': ':', 'brokers': {'broker1': {'host': 'localhost', 'port': 9092}}, 'topics': {'metrics': {'raw_topic_name_suffix': 'metrics', 'transformed_topic_name_suffix': 'processed'}}}, 'zookeeper': {'connection_timeout': 30, 'servers': {'server1': {'host': 'localhost', 'port': 2181}}}, 'discovery': {'plugins_paths': ['/home/panoptes/plugins/discovery'], 'plugin_scan_interval': 60, 'celerybeat_max_loop_interval': 5}, 'polling': {'plugins_paths': ['/home/panoptes/plugins/polling'], 'plugin_scan_interval': 90, 'celerybeat_max_loop_interval': 90}, 'enrichment': {'plugins_paths': ['/home/panoptes/plugins/enrichment'], 'plugin_scan_interval': 60, 'celerybeat_max_loop_interval': 5}, 'snmp': {'connection_factory_module': 'yahoo_panoptes.framework.utilities.snmp.connection', 'connection_factory_class': 'PanoptesSNMPConnectionFactory', 'community': '**', 'timeout': 5, 'retries': 1, 'non_repeaters': 0, 'max_repetitions': 25, 'port': 161, 'proxy_port': 10161, 'community_string_key': 'snmp_community_string'}, 'grpc': {'connection_factory_module': 'yahoo_panoptes.framework.utilities.grpc.connection', 'connection_factory_class': 'PanoptesGRPCConnectionFactory', 'timeout': 5, 'retries': 1, 'non_repeaters': 0, 'max_repetitions': 25, 'port': 32767}}), Redis pool set: False, Message producer set: False, Kafka client set: True, Zookeeper client set: False], KV store class: PanoptesDiscoveryPluginAgentKeyValueStore, Last executed timestamp: 1553833932, Last executed key: plugin_metadata:From_JSON_File_Discovery_Plugin:b5d7e0130618ca9daeec1e9c709fc262:last_executed, Last results timestamp: 1553833932, Last results key: plugin_metadata:From_JSON_File_Discovery_Plugin:b5d7e0130618ca9daeec1e9c709fc262:last_results, Data: None, Lock: Lock is set
[2019-03-29 10:22:45,624] [INFO] [runner] [info():74] [PID:23870 TID:140611731175232] [From JSON File Discovery Plugin:b5d7e0130618ca9daeec1e9c709fc262] [None] Attempting to get lock for plugin "From JSON File Discovery Plugin"
[2019-03-29 10:22:45,624] [INFO] [runner] [info():74] [PID:23870 TID:140611731175232] [From JSON File Discovery Plugin:b5d7e0130618ca9daeec1e9c709fc262] [None] -----
[2019-03-29 10:22:45,625] [INFO] [runner] [info():74] [PID:23870 TID:140611731175232] [From JSON File Discovery Plugin:b5d7e0130618ca9daeec1e9c709fc262] [None] calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/discovery//plugins/lock//From_JSON_File_Discovery_Plugin/b5d7e0130618ca9daeec1e9c709fc262, timeout=5, retries=1, identifier=50810e98-3c6a-4ad5-829a-6188f596dc22_plugin_ubuntu-14_23870
[2019-03-29 10:22:45,625] [INFO] [runner] [info():74] [PID:23870 TID:140611731175232] [From JSON File Discovery Plugin:b5d7e0130618ca9daeec1e9c709fc262] [None] False

But the contender lock(a2cd4734-3667-4450-90ad-559713289f7c_plugin_ubuntu-14_23850) is from scheduler

panoptes@ubuntu-14:~/log/discovery/scheduler$ grep a2cd4734-3667-4450-90ad-559713289f7c_plugin_ubuntu-14_23850 *
discovery_plugin_scheduler.log:[2019-03-29 10:20:39,519] [INFO] [lock] [_get_lock():70] [PID:23842 TID:139852627293952] Creating lock for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/discovery//plugins/lock//From_JSON_File_Discovery_Plugin/b5d7e0130618ca9daeec1e9c709fc262, timeout=5, retries=1, identifier=a2cd4734-3667-4450-90ad-559713289f7c_plugin_ubuntu-14_23850
discovery_plugin_scheduler.log:[2019-03-29 10:20:39,523] [INFO] [lock] [_get_lock():81] [PID:23842 TID:139852627293952] Trying to acquire lock for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/discovery//plugins/lock//From_JSON_File_Discovery_Plugin/b5d7e0130618ca9daeec1e9c709fc262, timeout=5, retries=1, identifier=a2cd4734-3667-4450-90ad-559713289f7c_plugin_ubuntu-14_23850. Other contenders: []
discovery_plugin_scheduler.log:[2019-03-29 10:20:39,539] [INFO] [lock] [_get_lock():96] [PID:23842 TID:139852627293952] Lock acquired for calling module: yahoo_panoptes.framework.plugins.panoptes_base_plugin, path=/panoptes/plugin_agent/discovery//plugins/lock//From_JSON_File_Discovery_Plugin/b5d7e0130618ca9daeec1e9c709fc262, timeout=5, retries=1, identifier=a2cd4734-3667-4450-90ad-559713289f7c_plugin_ubuntu-14_23850. Other contenders: [u'a2cd4734-3667-4450-90ad-559713289f7c_plugin_ubuntu-14_23850']

Can you please chekc and let know if my analysis is correct.

@varunvarma

This comment has been minimized.

Copy link
Contributor

commented Mar 29, 2019

Hey Sarath,

Something doesn't seem right here - the Discovery Plugin Scheduler logs should not have entries for locks under the plugin_agent path. The lock related entries in Discovery Plugin Scheduler would look like:

 [2019-03-29 17:38:03,858] [PID:11768 TID:139701123241728] [INFO] [lock] [_get_lock():81] Trying to acquire lock for calling module: yahoo.contrib.panoptes.discovery.discovery_plugin_scheduler, path=/panoptes/plugin_scheduler/discovery/lock, timeout=5, retries=0, identifier=a0218fb7-eac8-4581-a2fe-f8b395eef9fa_plugin_host_a_11768. Other contenders: [u'558ba151-81e1-47ec-a186-c2760542cdb3_plugin_host_b_8007', u'd9227672-03d6-4aa6-a74b-3d6f0f1ecb42_plugin_host_c_356841', u'212ec452-e89e-4cad-ba59-6e88f97b3cae_plugin_host_d_173833', u'bfb12392-8fd7-4a46-a343-bbcde4ae5ec6_plugin_host_d_365515', u'e09a000c-a6e3-4d99-8067-cc228a17c0e0_plugin_host_e_316819', u'e76391fa-40a9-4ff7-9fff-7be4aacb4312_plugin_host_f_395860', u'10b5934c-ad1d-4378-833a-e410e7c0f367_host_g_20894', u'0640a87b-f5a1-4a9c-93c6-84734c76db1b_host_h_216597', u'55b74dd9-39d7-4b3d-ae31-a2b3071e1ebf_plugin_host_i_264650']
 [2019-03-29 17:38:13,892] [PID:11768 TID:139701123241728] [INFO] [lock] [_get_lock():86] Timed out after 5 seconds trying to acquire lock for calling module: yahoo.contrib.panoptes.discovery.discovery_plugin_scheduler, path=/panoptes/plugin_scheduler/discovery/lock, timeout=5, retries=0, identifier=a0218fb7-eac8-4581-a2fe-f8b395eef9fa_plugin_host_a_11768

Where the format of the identifier is <guid>_<hostname>_<process id>

Would you mind sharing your logging.ini?

Regards,
-Varun

@d200201123

This comment has been minimized.

Copy link
Author

commented Mar 30, 2019

Attached logging.ini(Uploading with txt extension as .ini is not supported)

logging.ini.txt

Commands

Discovery Plugin Scheduler

mkdir -p /home/panoptes/log/discovery/scheduler
celery beat -A yahoo_panoptes.discovery.discovery_plugin_scheduler -l info -S yahoo_panoptes.framework.celery_manager.PanoptesCeleryPluginScheduler

Discovery Plugin Agent

mkdir -p /home/panoptes/log/discovery/agent
celery worker -A yahoo_panoptes.discovery.discovery_plugin_agent -l info -f /home/panoptes/log/discovery/agent/discovery_plugin_agent
@d200201123

This comment has been minimized.

Copy link
Author

commented Apr 8, 2019

Hi Varun,

Is the issue with lock for Discovery Plugin fixed.
I see the merge issue closed.

Regards,
Sarath

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.