diff --git a/Python_Engine/Python/src/python_toolkit/bhom/__init__.py b/Python_Engine/Python/src/python_toolkit/bhom/__init__.py index 28f3edc..bc0efd2 100644 --- a/Python_Engine/Python/src/python_toolkit/bhom/__init__.py +++ b/Python_Engine/Python/src/python_toolkit/bhom/__init__.py @@ -1,5 +1,6 @@ """Root for the bhom subpackage.""" +import os from pathlib import Path # pylint: disable=E0401 from os import path import tempfile @@ -9,6 +10,13 @@ TOOLKIT_NAME = "Python_Toolkit" BHOM_VERSION = importlib.metadata.version("python_toolkit") +#Environment variable that if set disables BHoM analytics logging. +DISABLE_ANALYTICS = os.environ.get("DISABLE_BHOM_ANALYTICS", None) +if DISABLE_ANALYTICS is None: + DISABLE_ANALYTICS = False +else: + DISABLE_ANALYTICS = True + if not BHOM_LOG_FOLDER.exists(): BHOM_LOG_FOLDER = Path(tempfile.gettempdir()) / "BHoM" / "Logs" BHOM_LOG_FOLDER.mkdir(exist_ok=True, parents=True) \ No newline at end of file diff --git a/Python_Engine/Python/src/python_toolkit/bhom/analytics.py b/Python_Engine/Python/src/python_toolkit/bhom/analytics.py index 0dcbf88..fbffddf 100644 --- a/Python_Engine/Python/src/python_toolkit/bhom/analytics.py +++ b/Python_Engine/Python/src/python_toolkit/bhom/analytics.py @@ -1,21 +1,128 @@ """BHoM analytics decorator.""" # pylint: disable=E0401 +import codecs +from dataclasses import dataclass, field import inspect +from itertools import groupby +import itertools import json +import os +from pathlib import Path +import socket import sys +import traceback import uuid from functools import wraps -from typing import Any, Callable +from typing import Any, Callable, Dict, List, Union from datetime import datetime # pylint: enable=E0401 -from .logging import ANALYTICS_LOGGER -from .util import csharp_ticks -from . import BHOM_VERSION, TOOLKIT_NAME, BHOM_LOG_FOLDER - - -def bhom_analytics() -> Callable: +from .logging import ANALYTICS_LOGGER, CONSOLE_LOGGER +from .util import bson_unix_ticks, bson_unix_ticks_to_datetime +from . import BHOM_VERSION, TOOLKIT_NAME, BHOM_LOG_FOLDER, DISABLE_ANALYTICS + +@dataclass +class UsageLogEntry(): + BHoMVersion:str = BHOM_VERSION + BHoM_Guid:uuid.UUID = uuid.uuid4() + CallerName:str = "" + ComponentId:uuid.UUID = uuid.uuid4() + CustomData:Dict = field(default_factory = {"interpreter", sys.executable}) + Errors:List[str] = field(default_factory = []) + FileId:str = "" + FileName:str = "" + Fragments:List[str] = field(default_factory = []) + Name:str = "" + ProjectID:str = "" + SelectedItem:Dict = field(default_factory = {"MethodName": "", "Parameters": [], "TypeName": ""}) + Time:Dict = field(default_factory = {"$date": 0}) + UI:str = "Python" + UiVersion:str = sys.version + _t:str = "BH.oM.Base.UsageLogEntry" + + @classmethod + def from_json(cls, json_str:str) -> 'UsageLogEntry': + d = json.loads(json_str) + if "CustomData" not in d: + d["CustomData"] = None + if "Fragments" not in d: + d["Fragments"] = None + return UsageLogEntry(d["BHoMVersion"], d["BHoM_Guid"], d["CallerName"], d["ComponentId"], d["CustomData"], d["Errors"], d["FileId"], d["FileName"], d["Fragments"], d["Name"], d["ProjectID"], d["SelectedItem"], d["Time"], d["UI"], d["UiVersion"]) + +def load_logs_from_file(filename:str) -> List[UsageLogEntry]: + logs:List[UsageLogEntry] = [] + + #adapted from https://stackoverflow.com/questions/30629297/remove-byte-order-mark-from-objects-in-a-list + #due to some files generated by BHoM logs being encoded with utf-8 BOM instead of utf-8 + with open(filename, "r") as f: + lines = f.readlines() + if lines[0].__contains__(codecs.BOM_UTF8.decode(f.encoding)): + # A Byte Order Mark is present + lines[0] = lines[0].strip(codecs.BOM_UTF8.decode(f.encoding)) + for line in lines: + if len(line) != 0: + logs.append(UsageLogEntry.from_json(line)) + + return logs + +def summarise_usage_logs(usage_log_entries:List[UsageLogEntry]) -> List[Dict]: + db_entries:List[Dict] = [] + + usage_log_entries.sort(key=lambda x: x.ProjectID) + + for file_id, filegroup in groupby(usage_log_entries, lambda x: x.FileId): + filegroup = list(filegroup) + project_id = filegroup[0].ProjectID + filename = filegroup[0].FileName + filegroup.sort(key = lambda x: x.CallerName + str(x.SelectedItem)) + + for method_name, methodgroup in groupby(filegroup, lambda x: x.CallerName + str(x.SelectedItem)): + methodgroup = list(methodgroup) + first_entry = methodgroup[0] + + db_entries.append({ + "StartTime": bson_unix_ticks_to_datetime(min(methodgroup, key=lambda x: x.Time["$date"]).Time["$date"], short=True), + "EndTime": bson_unix_ticks_to_datetime(max(methodgroup, key=lambda x: x.Time["$date"]).Time["$date"], short=True), + "UI": first_entry.UI, + "UiVersion":first_entry.UiVersion, + "CallerName": first_entry.CallerName, + "SelectedItem": first_entry.SelectedItem, + "Computer": socket.gethostname(), + "UserName": os.environ.get("USERNAME"), + "BHoMVersion": BHOM_VERSION, + "FileId": file_id, + "FileName": filename, + "ProjectID": project_id, + "NbCallingComponents": len(set([a.ComponentId for a in methodgroup])), + "TotalNbCals": len(methodgroup), + "Errors": list(itertools.chain.from_iterable([x.Errors for x in methodgroup])), + "_t": "BH.oM.BHoMAnalytics.UsageEntry" + }) + + return db_entries + +def convert_exc_info_to_bhom_error(exc_info): + time = bson_unix_ticks(datetime.now(), short=True) + utcTime = bson_unix_ticks(short=True) + stack_trace = traceback.extract_tb(exc_info[3]) + message = str(exc_info[1]) + Type = "Error" #using string but ideally this would be an enum value. + return {"Time": {"$date": time}, "UtcTime": {"$date": utcTime}, "StackTrace": stack_trace, "Message": message, "Type": Type, "_t": "BH.oM.Base.Debugging.Event"} + +global PROJECT_NUMBER +PROJECT_NUMBER = None + +def set_project_number(project_number: Union[str, None]): + global PROJECT_NUMBER + CONSOLE_LOGGER.debug(f"Setting project number: {PROJECT_NUMBER} to {project_number}") + PROJECT_NUMBER = project_number + +def get_project_number() -> Union[str, None]: + CONSOLE_LOGGER.debug(f"Retrieving project number: {PROJECT_NUMBER}") + return PROJECT_NUMBER + +def bhom_analytics(project_id:Callable = get_project_number, disable:bool = DISABLE_ANALYTICS) -> Callable: """Decorator for capturing usage data. Returns @@ -24,6 +131,8 @@ def bhom_analytics() -> Callable: The decorated function. """ + _componentId = uuid.uuid4() + def decorator(function: Callable): """A decorator to capture usage data for called methods/functions. @@ -42,8 +151,15 @@ def decorator(function: Callable): def wrapper(*args, **kwargs) -> Any: """A wrapper around the function that captures usage analytics.""" + if disable: + CONSOLE_LOGGER.debug("bhom_analytics is curently disabled.") + return function(*args, **kwargs) + _id = uuid.uuid4() + #for now for file IDs, generate one using the project ID + file_id = uuid.uuid3(uuid.NAMESPACE_OID, project_id()) + # get the data being passed to the function, expected dtype and return type argspec = inspect.getfullargspec(function)[-1] argspec.pop("return", None) @@ -54,36 +170,34 @@ def wrapper(*args, **kwargs) -> Any: "BHoMVersion": BHOM_VERSION, "BHoM_Guid": _id, "CallerName": function.__name__, - "ComponentId": _id, - "CustomData": {"interpreter", sys.executable}, + "ComponentId": _componentId, + "CustomData": {"interpreter": sys.executable}, "Errors": [], - "FileId": "", - "FileName": "", + "FileId": str(file_id), + "FileName": str(file_id), "Fragments": [], "Name": "", - # TODO - get project properties from another function/logging - # method (or from BHoM DLL analytics capture ...) - "ProjectID": "", + "ProjectID": project_id(), "SelectedItem": { "MethodName": function.__name__, "Parameters": _args, "TypeName": f"{function.__module__}.{function.__qualname__}" }, "Time": { - "$date": csharp_ticks(short=True), + "$date": bson_unix_ticks(short=True), }, "UI": "Python", - "UiVersion": TOOLKIT_NAME, + "UiVersion": sys.version, "_t": "BH.oM.Base.UsageLogEntry", } try: result = function(*args, **kwargs) except Exception as exc: # pylint: disable=broad-except - exec_metadata["Errors"].extend(sys.exc_info()) + exec_metadata["Errors"].extend(convert_exc_info_to_bhom_error(sys.exc_info())) raise exc finally: - log_file = BHOM_LOG_FOLDER / f"{function.__module__.split('.')[0]}_{datetime.now().strftime('%Y%m%d')}.log" + log_file = BHOM_LOG_FOLDER / f"Usage_{function.__module__.split('.')[0]}_{datetime.now().strftime('%Y%m%d')}.log" if ANALYTICS_LOGGER.handlers[0].baseFilename != str(log_file): ANALYTICS_LOGGER.handlers[0].close() diff --git a/Python_Engine/Python/src/python_toolkit/bhom/logging/console.py b/Python_Engine/Python/src/python_toolkit/bhom/logging/console.py index d36178b..029dc9a 100644 --- a/Python_Engine/Python/src/python_toolkit/bhom/logging/console.py +++ b/Python_Engine/Python/src/python_toolkit/bhom/logging/console.py @@ -8,12 +8,14 @@ from .. import TOOLKIT_NAME +level = logging.INFO + formatter = logging.Formatter("%(name)s - %(levelname)s - %(message)s") handler = logging.StreamHandler(sys.stdout) -handler.setLevel(logging.DEBUG) +handler.setLevel(level) handler.setFormatter(formatter) CONSOLE_LOGGER = logging.getLogger(f"{TOOLKIT_NAME}[console]") CONSOLE_LOGGER.propagate = False -CONSOLE_LOGGER.setLevel(logging.DEBUG) +CONSOLE_LOGGER.setLevel(level) CONSOLE_LOGGER.addHandler(handler) diff --git a/Python_Engine/Python/src/python_toolkit/bhom/util.py b/Python_Engine/Python/src/python_toolkit/bhom/util.py index 3200384..f5491f7 100644 --- a/Python_Engine/Python/src/python_toolkit/bhom/util.py +++ b/Python_Engine/Python/src/python_toolkit/bhom/util.py @@ -1,12 +1,11 @@ """General utility functions.""" # pylint: disable=E0401 -from datetime import datetime - +from datetime import datetime, timedelta # pylint: enable=E0401 -def csharp_ticks(date_time: datetime = datetime.utcnow(), short: bool = False) -> int: - """Python implementation of C# DateTime.UtcNow.Ticks. +def bson_unix_ticks(date_time: datetime = datetime.utcnow(), short: bool = False) -> int: + """Python implementation of unix ticks. Args: date_time (datetime, optional): The datetime to convert to ticks. Defaults to datetime.utcnow(). @@ -16,9 +15,16 @@ def csharp_ticks(date_time: datetime = datetime.utcnow(), short: bool = False) - int: The ticks. """ - _ticks = (date_time - datetime(1, 1, 1)).total_seconds() + _ticks = (date_time - datetime(1970, 1, 1)).total_seconds() * 10**3 if short: return int(_ticks) - return int(_ticks * (10**7)) + return int(_ticks * (10**4)) + +def bson_unix_ticks_to_datetime(ticks: int, short:bool = False) -> datetime: + + if not short: + _ticks *= (10**-4) + + return datetime(1, 1, 1) + timedelta(milliseconds=ticks) \ No newline at end of file