|
|
|
@ -135,45 +135,132 @@ def clean_ansi(text):
|
|
|
|
|
return ansi_escape.sub('', text)
|
|
|
|
|
|
|
|
|
|
def format_number(number_str):
|
|
|
|
|
number = int(number_str)
|
|
|
|
|
if number >= 1000:
|
|
|
|
|
return f"{number//1000}k"
|
|
|
|
|
return str(number)
|
|
|
|
|
try:
|
|
|
|
|
number = int(number_str)
|
|
|
|
|
if number >= 1000:
|
|
|
|
|
value_in_k = number / 1000.0
|
|
|
|
|
# Format to 3 decimal places if needed, remove trailing zeros and potentially the dot
|
|
|
|
|
formatted_num = f"{value_in_k:.3f}".rstrip('0').rstrip('.')
|
|
|
|
|
return f"{formatted_num}k"
|
|
|
|
|
return str(number)
|
|
|
|
|
except (ValueError, TypeError):
|
|
|
|
|
return "NaN" # Or some other indicator of invalid input
|
|
|
|
|
|
|
|
|
|
def check_logs(logger, initial_sync_count, previous_status):
|
|
|
|
|
"""
|
|
|
|
|
Checks docker logs for node status (Syncing, OK, Idle) and updates sync count.
|
|
|
|
|
|
|
|
|
|
Args:
|
|
|
|
|
logger: The logger instance.
|
|
|
|
|
initial_sync_count: The sync count read from Grist at the start.
|
|
|
|
|
previous_status: The last known status read from Grist ('Sync', 'OK', 'Idle', or others).
|
|
|
|
|
|
|
|
|
|
Returns:
|
|
|
|
|
A dictionary containing:
|
|
|
|
|
- status_message: A string describing the current status (e.g., "Sync: 123k (5)").
|
|
|
|
|
- current_status_type: The type of the current status ('Sync', 'OK', 'Idle', 'Error').
|
|
|
|
|
- current_sync_count: The updated sync count.
|
|
|
|
|
"""
|
|
|
|
|
current_sync_count = initial_sync_count # Initialize with the value from Grist
|
|
|
|
|
|
|
|
|
|
def check_logs(logger):
|
|
|
|
|
try:
|
|
|
|
|
logs = subprocess.run(['docker', 'logs', '--since', '10m', 'infernet-node'], capture_output=True, text=True, check=True)
|
|
|
|
|
log_content = clean_ansi(logs.stdout)
|
|
|
|
|
|
|
|
|
|
last_subscription_id = None
|
|
|
|
|
head_sub_id = None
|
|
|
|
|
|
|
|
|
|
for line in log_content.splitlines():
|
|
|
|
|
if "Ignored subscription creation" in line and "id=" in line:
|
|
|
|
|
id_match = re.search(r'id=(\d+)', line)
|
|
|
|
|
if id_match:
|
|
|
|
|
last_subscription_id = id_match.group(1)
|
|
|
|
|
|
|
|
|
|
if "head sub id is:" in line:
|
|
|
|
|
id_match = re.search(r'head sub id is:\s*(\d+)', line)
|
|
|
|
|
if id_match:
|
|
|
|
|
head_sub_id = id_match.group(1)
|
|
|
|
|
|
|
|
|
|
if last_subscription_id:
|
|
|
|
|
logger.info(f"Subscription: {last_subscription_id}")
|
|
|
|
|
return {"status": f"Sync: {format_number(last_subscription_id)}"}
|
|
|
|
|
|
|
|
|
|
if head_sub_id:
|
|
|
|
|
logger.info(f"Head sub id: {head_sub_id}")
|
|
|
|
|
return {"status": f"OK: {head_sub_id}"}
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
logger.info("Not found subscription")
|
|
|
|
|
return {"status": "Idle"}
|
|
|
|
|
|
|
|
|
|
except subprocess.CalledProcessError as e:
|
|
|
|
|
raise RuntimeError(f"Error running docker logs: {e}")
|
|
|
|
|
|
|
|
|
|
last_checking_info = None
|
|
|
|
|
last_ignored_id = None
|
|
|
|
|
last_head_sub_id = None
|
|
|
|
|
|
|
|
|
|
# Regex patterns
|
|
|
|
|
checking_pattern = re.compile(r'Checking subscriptions.*last_sub_id=(\d+).*head_sub_id=(\d+).*num_subs_to_sync=(\d+)')
|
|
|
|
|
ignored_pattern = re.compile(r'Ignored subscription creation.*id=(\d+)')
|
|
|
|
|
head_sub_pattern = re.compile(r'head sub id is:\s*(\d+)')
|
|
|
|
|
|
|
|
|
|
# Use deque to efficiently get the last few relevant lines if needed,
|
|
|
|
|
# but processing all lines and keeping the last match is simpler here.
|
|
|
|
|
for line in log_content.splitlines():
|
|
|
|
|
match = checking_pattern.search(line)
|
|
|
|
|
if match:
|
|
|
|
|
last_checking_info = {
|
|
|
|
|
"last_sub_id": match.group(1),
|
|
|
|
|
"head_sub_id": match.group(2),
|
|
|
|
|
"num_subs_to_sync": int(match.group(3))
|
|
|
|
|
}
|
|
|
|
|
continue # Prioritize checking_info
|
|
|
|
|
|
|
|
|
|
match = ignored_pattern.search(line)
|
|
|
|
|
if match:
|
|
|
|
|
last_ignored_id = match.group(1)
|
|
|
|
|
continue
|
|
|
|
|
|
|
|
|
|
match = head_sub_pattern.search(line)
|
|
|
|
|
if match:
|
|
|
|
|
last_head_sub_id = match.group(1)
|
|
|
|
|
# No continue here, allows checking_info from same timeframe to override
|
|
|
|
|
|
|
|
|
|
current_status_type = "Idle"
|
|
|
|
|
status_message = "Idle"
|
|
|
|
|
|
|
|
|
|
if last_checking_info:
|
|
|
|
|
formatted_id = format_number(last_checking_info["last_sub_id"])
|
|
|
|
|
if last_checking_info["num_subs_to_sync"] > 0:
|
|
|
|
|
current_status_type = "Sync"
|
|
|
|
|
status_message = f"Sync: {formatted_id}" # Use current_sync_count
|
|
|
|
|
logger.info(f"Node is syncing. Last sub ID: {last_checking_info['last_sub_id']}, Num subs to sync: {last_checking_info['num_subs_to_sync']}")
|
|
|
|
|
else:
|
|
|
|
|
current_status_type = "OK"
|
|
|
|
|
# Increment count only on transition from Sync to OK
|
|
|
|
|
if previous_status == "Sync":
|
|
|
|
|
current_sync_count += 1 # Increment local count
|
|
|
|
|
logger.info(f"Sync completed. Sync count incremented to {current_sync_count}.")
|
|
|
|
|
status_message = f"OK: {formatted_id}" # Use current_sync_count
|
|
|
|
|
logger.info(f"Node is OK. Last sub ID: {last_checking_info['last_sub_id']}")
|
|
|
|
|
|
|
|
|
|
elif last_ignored_id:
|
|
|
|
|
# Fallback to "Ignored" logs if "Checking" is missing
|
|
|
|
|
formatted_id = format_number(last_ignored_id)
|
|
|
|
|
current_status_type = "Sync" # Assume sync if we only see ignored creations recently
|
|
|
|
|
status_message = f"Sync: {formatted_id}" # Use current_sync_count
|
|
|
|
|
logger.info(f"Node possibly syncing (based on ignored logs). Last ignored ID: {last_ignored_id}")
|
|
|
|
|
|
|
|
|
|
elif last_head_sub_id:
|
|
|
|
|
# Fallback to "head sub id" if others are missing
|
|
|
|
|
formatted_id = format_number(last_head_sub_id)
|
|
|
|
|
current_status_type = "OK" # Assume OK if this is the latest relevant info
|
|
|
|
|
# Don't increment sync count here, only on Sync -> OK transition based on "Checking" logs
|
|
|
|
|
status_message = f"OK: {formatted_id}" # Use current_sync_count
|
|
|
|
|
logger.info(f"Node status based on head sub id. Head sub ID: {last_head_sub_id}")
|
|
|
|
|
|
|
|
|
|
else:
|
|
|
|
|
logger.info("No relevant subscription log entries found in the last 10 minutes. Status: Idle.")
|
|
|
|
|
status_message = "Idle"
|
|
|
|
|
current_status_type = "Idle"
|
|
|
|
|
|
|
|
|
|
# Return the results instead of writing to a file
|
|
|
|
|
return {
|
|
|
|
|
"status_message": status_message,
|
|
|
|
|
"current_status_type": current_status_type,
|
|
|
|
|
"current_sync_count": current_sync_count
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
except subprocess.CalledProcessError as e:
|
|
|
|
|
error_msg = f"Error: Docker logs failed ({e.returncode})"
|
|
|
|
|
logger.error(f"Error running docker logs command: {e.stderr or e.stdout or e}")
|
|
|
|
|
# Return error status and original sync count
|
|
|
|
|
return {
|
|
|
|
|
"status_message": error_msg,
|
|
|
|
|
"current_status_type": "Error",
|
|
|
|
|
"current_sync_count": initial_sync_count # Return original count on error
|
|
|
|
|
}
|
|
|
|
|
except Exception as e:
|
|
|
|
|
error_msg = "Error: Log processing failed"
|
|
|
|
|
logger.error(f"Unexpected error processing logs: {e}", exc_info=True)
|
|
|
|
|
# Return error status and original sync count
|
|
|
|
|
return {
|
|
|
|
|
"status_message": error_msg,
|
|
|
|
|
"current_status_type": "Error",
|
|
|
|
|
"current_sync_count": initial_sync_count # Return original count on error
|
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
if __name__ == "__main__":
|
|
|
|
|
colorama.init(autoreset=True)
|
|
|
|
@ -200,15 +287,88 @@ if __name__ == "__main__":
|
|
|
|
|
current_vm = grist.find_record(name=GRIST_ROW_NAME, table=NODES_TABLE)[0]
|
|
|
|
|
def grist_callback(msg): grist.update(current_vm.id, msg, NODES_TABLE)
|
|
|
|
|
|
|
|
|
|
# Initialize updates dictionary
|
|
|
|
|
initial_updates = {}
|
|
|
|
|
# Check and prepare update for Syncs if it's None or empty
|
|
|
|
|
if not current_vm.Syncs: # Handles None, empty string, potentially 0 if that's how Grist stores it
|
|
|
|
|
initial_updates["Syncs"] = 0
|
|
|
|
|
# Check and prepare update for Reboots if it's None or empty
|
|
|
|
|
if not current_vm.Reboots: # Handles None, empty string, potentially 0
|
|
|
|
|
initial_updates["Reboots"] = 0
|
|
|
|
|
|
|
|
|
|
# If there are updates, send them to Grist
|
|
|
|
|
if initial_updates:
|
|
|
|
|
try:
|
|
|
|
|
logger.info(f"Found empty initial values, updating Grist: {initial_updates}")
|
|
|
|
|
grist.update(current_vm.id, initial_updates, NODES_TABLE)
|
|
|
|
|
# Re-fetch the record to ensure subsequent logic uses the updated values
|
|
|
|
|
current_vm = grist.find_record(name=GRIST_ROW_NAME, table=NODES_TABLE)[0]
|
|
|
|
|
logger.info("Grist updated successfully with initial zeros.")
|
|
|
|
|
except Exception as e:
|
|
|
|
|
logger.error(f"Failed to update Grist with initial zeros: {e}")
|
|
|
|
|
# Decide how to proceed: maybe exit, maybe continue with potentially incorrect defaults
|
|
|
|
|
# For now, we'll log the error and continue using the potentially incorrect defaults from the first fetch
|
|
|
|
|
|
|
|
|
|
# Get initial state from Grist (now potentially updated)
|
|
|
|
|
initial_sync_count = int(current_vm.Syncs or 0) # 'or 0' still useful as fallback
|
|
|
|
|
reboot_count = int(current_vm.Reboots or 0) # 'or 0' still useful as fallback
|
|
|
|
|
# Determine previous status type based on Health string (simplified)
|
|
|
|
|
previous_health_status = current_vm.Health or "Idle"
|
|
|
|
|
previous_status_type = "Idle" # Default
|
|
|
|
|
if previous_health_status.startswith("Sync"):
|
|
|
|
|
previous_status_type = "Sync"
|
|
|
|
|
elif previous_health_status.startswith("OK"):
|
|
|
|
|
previous_status_type = "OK"
|
|
|
|
|
elif previous_health_status.startswith("Error"):
|
|
|
|
|
previous_status_type = "Error" # Consider error state
|
|
|
|
|
|
|
|
|
|
logger.info(f"Initial state from Grist - Syncs: {initial_sync_count}, Health: {previous_health_status}, Reboots: {reboot_count}")
|
|
|
|
|
|
|
|
|
|
for attempt in range(3):
|
|
|
|
|
try:
|
|
|
|
|
result = check_logs(logger)
|
|
|
|
|
grist_callback({ "Health": result["status"] })
|
|
|
|
|
logger.info(f"Status: {result['status']}")
|
|
|
|
|
break
|
|
|
|
|
except Exception as e:
|
|
|
|
|
logger.error(f"Error on attempt {attempt+1}/3: {e}")
|
|
|
|
|
try:
|
|
|
|
|
vm_ip = os.popen("ip -4 addr show eth0 | grep -oP '(?<=inet )[^/]+'").read()
|
|
|
|
|
vm_ip = vm_ip.strip()
|
|
|
|
|
if vm_ip == "":
|
|
|
|
|
logger.error("Failed to get VM IP address")
|
|
|
|
|
else:
|
|
|
|
|
logger.info(f"VM IP address: {vm_ip}")
|
|
|
|
|
grist_callback({"IP": f"{vm_ip}"})
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
# Pass initial state to check_logs
|
|
|
|
|
result = check_logs(logger, initial_sync_count, previous_status_type)
|
|
|
|
|
|
|
|
|
|
grist_updates = {"Health": result["status_message"]}
|
|
|
|
|
|
|
|
|
|
# Update Syncs count in Grist only if it changed
|
|
|
|
|
if result["current_sync_count"] != initial_sync_count:
|
|
|
|
|
grist_updates["Syncs"] = result["current_sync_count"]
|
|
|
|
|
logger.info(f"Sync count changed from {initial_sync_count} to {result['current_sync_count']}")
|
|
|
|
|
|
|
|
|
|
# Send updates to Grist
|
|
|
|
|
grist_callback(grist_updates)
|
|
|
|
|
logger.info(f"Status update sent: {grist_updates}")
|
|
|
|
|
|
|
|
|
|
# Reboot logic (remains mostly the same, reads Reboots from current_vm)
|
|
|
|
|
if result["current_status_type"] == "Idle": # Check type, not message
|
|
|
|
|
uptime_seconds = os.popen("cat /proc/uptime | cut -d'.' -f1").read()
|
|
|
|
|
uptime_seconds = int(uptime_seconds)
|
|
|
|
|
if uptime_seconds > 60*60*4:
|
|
|
|
|
reboot_count = int(current_vm.Reboots or 0)
|
|
|
|
|
reboot_count += 1
|
|
|
|
|
# Include reboot count in the final Grist update before rebooting
|
|
|
|
|
grist_updates = { "Health": "Rebooting", "Reboots": reboot_count }
|
|
|
|
|
grist_callback(grist_updates)
|
|
|
|
|
logger.info(f"Idle detected for >4 hours (uptime: {uptime_seconds}s). Rebooting. Reboot count: {reboot_count}")
|
|
|
|
|
os.system("reboot")
|
|
|
|
|
break # Exit loop on success
|
|
|
|
|
except Exception as e:
|
|
|
|
|
logger.error(f"Error in main loop, attempt {attempt+1}/3: {e}", exc_info=True)
|
|
|
|
|
if attempt == 2:
|
|
|
|
|
grist_callback({ "Health": f"Error: {e}" })
|
|
|
|
|
if attempt < 2:
|
|
|
|
|
time.sleep(5)
|
|
|
|
|
# Log final error to Grist on last attempt
|
|
|
|
|
try:
|
|
|
|
|
grist_updates = { "Health": f"Error: Main loop failed - {e}" }
|
|
|
|
|
grist_callback(grist_updates)
|
|
|
|
|
except Exception as grist_e:
|
|
|
|
|
logger.error(f"Failed to log final error to Grist: {grist_e}")
|
|
|
|
|
time.sleep(5) # Wait before retrying
|
|
|
|
|