Implement log flushing #808

nkaretnikov · 2024-04-11T16:52:18Z

Fixes #809.

Description

This pull request:

makes actions write to log storage incrementally: the output can be seen by users as soon as it's available
changes the logging format by prefixing each line with the name of the action: makes it easier to see what code is running
adds locking when appending to logs to avoid a race condition
moves the body of logged_command to ActionContext.run_command, next to run.

Pull request checklist

Did you test this change locally?
Did you update the documentation (if required)?
Did you add/update relevant tests for this change (if required)?

Additional information

How to test

start an environment build
go to the logs page for this build
check that new output appears while an action is running, by refreshing the page quickly
check that all output is prefixed with the action name

netlify · 2024-04-11T16:52:34Z

✅ Deploy Preview for conda-store canceled.

Name	Link
🔨 Latest commit	`b09a067`
🔍 Latest deploy log	https://app.netlify.com/sites/conda-store/deploys/663193c2a4ffeb0008d7dfbf

nkaretnikov · 2024-04-15T02:05:18Z

conda-store-server/conda_store_server/build.py

-    except Exception:
-        current_logs = b""
+class LoggedStream:
+    """Allows writing to storage via logging.StreamHandler"""


This class is designed to be used with StreamHandler, via self.log in ActionContext, as well as a dedicated stream, via self.stdout and self.stderr. This allows capturing output no matter how it's written to, by writing to one of the streams directly or using the logging library, and without changing existing logging code.

From https://docs.python.org/3/library/logging.handlers.html#streamhandler:

The StreamHandler class, located in the core logging package, sends logging output to streams such as sys.stdout, sys.stderr or any file-like object (or, more precisely, any object which supports write() and flush() methods).

Can you leave this useful information in the docstring?

nkaretnikov · 2024-04-15T02:28:47Z

conda-store-server/conda_store_server/action/base.py

+            stderr=subprocess.STDOUT if redirect_stderr else subprocess.PIPE,
+            bufsize=1,
+            universal_newlines=True,
+            **kwargs,


https://docs.python.org/3/library/subprocess.html

bufsize [...] 1 means line buffered (only usable if text=True or universal_newlines=True)

Might be useful to put this in the code (in the docstring, maybe?)

nkaretnikov · 2024-04-15T04:32:05Z

conda-store-server/conda_store_server/storage.py

-        db.commit()
+        if not exists:
+            db.add(ba(build_id=build_id, key=key, artifact_type=artifact_type))
+            db.commit()


nkaretnikov · 2024-04-21T09:42:57Z

@dcmcand @peytondmurray A gentle reminder that this still needs review. Will rebase after it's approved.

peytondmurray

Thanks for this! I think it's basically there but adding (and moving some of the existing) explanatory documentation to be in docstrings would help with future maintenance.

Does it also make sense to write tests for this? e.g. run an action, expect some logging output with the appropriate logging prefix, etc.

I still need to run this locally to see what difference there is here, but will report back.

peytondmurray · 2024-04-23T01:54:35Z

conda-store-server/conda_store_server/action/base.py

        self.log = logging.getLogger(f"conda_store_server.action.{self.id}")
        self.log.propagate = False
        self.log.addHandler(logging.StreamHandler(stream=self.stdout))
        self.log.setLevel(logging.INFO)
        self.result = None
        self.artifacts = {}

+    def run_command(self, command, redirect_stderr=True, **kwargs):
+        """Runs command and immediately writes to logs"""


The bulk of this function has to do with redirecting output to context buffers from the subprocess, so it might make sense to mention something about that in the docstring.

I know this isn't done elsewhere in the code, so maybe it would be useful to discuss in tomorrow's meeting about docstrings and type annotations. But IMO it would make future future maintenance easier if there was something said about each parameter, e.g. why is there an option to redirect stderr but not stdout? Part of the reason I mention it is that LSPs will pull out docstrings and type annotations to give richer hints if we use those, and doing so will unlock static type checking in the future.

peytondmurray · 2024-04-23T01:55:29Z

conda-store-server/conda_store_server/action/base.py

+            stderr=subprocess.STDOUT if redirect_stderr else subprocess.PIPE,
+            bufsize=1,
+            universal_newlines=True,
+            **kwargs,


Might be useful to put this in the code (in the docstring, maybe?)

peytondmurray · 2024-04-23T01:58:49Z

conda-store-server/conda_store_server/action/generate_constructor_installer.py

@@ -40,7 +40,7 @@ def write_file(filename, s):
            "constructor",
            "--help",
        ]
-        logged_command(context, command, timeout=10)
+        logged_command(context, command)


Suggested change

logged_command(context, command)

context.run_command(command)

Based on your comment under the logged_command function.

peytondmurray · 2024-04-23T02:00:50Z

conda-store-server/conda_store_server/build.py

-    except Exception:
-        current_logs = b""
+class LoggedStream:
+    """Allows writing to storage via logging.StreamHandler"""


Can you leave this useful information in the docstring?

peytondmurray · 2024-04-23T02:08:18Z

conda-store-server/conda_store_server/build.py

+    # For instance, with local storage, this involves reading from and writing
+    # to a file. Locking here prevents a race condition when multiple tasks
+    # attempt to write to a shared resource, which is the log
+    with FileLock(f"{build.build_path(conda_store)}.log.lock"):


Does it make sense to have a timeout here? This lock is only active during writes to the file, not actual commands running, right? If so, something short (5s?) should be okay.

peytondmurray · 2024-04-23T02:10:01Z

conda-store-server/conda_store_server/build.py

+        pass
+
+
+def append_to_logs(db: Session, conda_store, build, logs: typing.Union[str, bytes]):


Would it be okay to add types for the other parameters?

peytondmurray · 2024-04-23T02:11:40Z

conda-store-server/conda_store_server/build.py


-    if isinstance(logs, str):
-        logs = logs.encode("utf-8")
+    def __init__(self, db, conda_store, build, prefix=None):


If you want, the default can be prefix = "", which would eliminate the need for the branch on L34.

peytondmurray · 2024-04-23T02:12:09Z

conda-store-server/conda_store_server/build.py

+                line = self.prefix + line
+            append_to_logs(self.db, self.conda_store, self.build, line + "\n")
+
+    def flush(self):


Is this needed?

peytondmurray · 2024-04-23T02:16:41Z

conda-store-server/conda_store_server/storage.py

+        ba = orm.BuildArtifact
+        exists = (
+            db.query(ba)
+            .filter(ba.build_id == build_id)
+            .filter(ba.key == key)
+            .filter(ba.artifact_type == artifact_type)
+            .first()
        )
-        db.commit()
+        if not exists:
+            db.add(ba(build_id=build_id, key=key, artifact_type=artifact_type))
+            db.commit()


Looks the same as Storage.fset. Can we just call that?

peytondmurray · 2024-04-23T02:17:05Z

conda-store-server/conda_store_server/action/utils.py

-            command, stderr=subprocess.STDOUT, encoding="utf-8", **kwargs
-        )
-    )
+    # This is here only for backward compatibility, new code should use the


Does it make sense to issue a DeprecationWarning here? cc @dcmcand for insight about our policy around this.

This reverts commit 71761ba.

Co-authored-by: pre-commit-ci[bot] <66853113+pre-commit-ci[bot]@users.noreply.github.com>

nkaretnikov force-pushed the improve-logs-806 branch from ddf7cc4 to 5ac779e Compare April 14, 2024 21:00

nkaretnikov changed the title ~~WIP: Move conda-lock into a subprocess~~ Implement log flushing Apr 14, 2024

nkaretnikov mentioned this pull request Apr 14, 2024

[ENH] - Implement log flushing #809

Closed

nkaretnikov added type: enhancement 💅🏼 status: in progress 🏗 area: user experience 👩🏻‍💻 Items impacting the end-user experience project: challenges labels Apr 15, 2024

nkaretnikov added this to the challenges: Round 2 🚀 milestone Apr 15, 2024

nkaretnikov commented Apr 15, 2024

View reviewed changes

nkaretnikov marked this pull request as ready for review April 15, 2024 04:44

nkaretnikov requested review from dcmcand and peytondmurray April 15, 2024 04:44

nkaretnikov added the needs: review 👀 label Apr 15, 2024

peytondmurray approved these changes Apr 23, 2024

View reviewed changes

peytondmurray removed this from the challenges: Round 2 🚀 milestone Apr 23, 2024

nkaretnikov and others added 7 commits April 30, 2024 13:48

Move conda-lock into a subprocess

4e1fde2

Log subprocess output periodically

b0378b2

Revert "Move conda-lock into a subprocess"

f308fd2

This reverts commit 71761ba.

[pre-commit.ci] Apply automatic pre-commit fixes

3e191fa

Fix linting issues

a1b0f33

Use locking when appending to log storage

1e937b4

Bug fix: avoid inserting duplicate log entries

b09a067

nkaretnikov removed the needs: review 👀 label May 1, 2024

nkaretnikov force-pushed the improve-logs-806 branch from ed100a1 to b09a067 Compare May 1, 2024 00:58

nkaretnikov merged commit 42ce8c0 into conda-incubator:main May 1, 2024
27 checks passed

nkaretnikov removed the status: in progress 🏗 label May 1, 2024

peytondmurray pushed a commit to peytondmurray/conda-store that referenced this pull request May 4, 2024

Implement log flushing (conda-incubator#808)

dc6138a

Co-authored-by: pre-commit-ci[bot] <66853113+pre-commit-ci[bot]@users.noreply.github.com>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Implement log flushing #808

Implement log flushing #808

nkaretnikov commented Apr 11, 2024 •

edited

Loading

netlify bot commented Apr 11, 2024 •

edited

Loading

nkaretnikov Apr 15, 2024 •

edited

Loading

peytondmurray Apr 23, 2024

nkaretnikov Apr 15, 2024

peytondmurray Apr 23, 2024

nkaretnikov Apr 15, 2024

nkaretnikov commented Apr 21, 2024

peytondmurray left a comment •

edited

Loading

peytondmurray Apr 23, 2024

peytondmurray Apr 23, 2024

peytondmurray Apr 23, 2024

peytondmurray Apr 23, 2024

peytondmurray Apr 23, 2024

peytondmurray Apr 23, 2024

peytondmurray Apr 23, 2024

peytondmurray Apr 23, 2024

peytondmurray Apr 23, 2024

peytondmurray Apr 23, 2024

	logged_command(context, command)
	context.run_command(command)

		pass


		def append_to_logs(db: Session, conda_store, build, logs: typing.Union[str, bytes]):

Implement log flushing #808

Implement log flushing #808

Conversation

nkaretnikov commented Apr 11, 2024 • edited Loading

Description

Pull request checklist

Additional information

How to test

netlify bot commented Apr 11, 2024 • edited Loading

✅ Deploy Preview for conda-store canceled.

nkaretnikov Apr 15, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nkaretnikov commented Apr 21, 2024

peytondmurray left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nkaretnikov commented Apr 11, 2024 •

edited

Loading

netlify bot commented Apr 11, 2024 •

edited

Loading

nkaretnikov Apr 15, 2024 •

edited

Loading

peytondmurray left a comment •

edited

Loading