added timestamp to log lines by default

[bachsh]

Following discussion here

[jsignell]

This seems like a nice improvement! Unfortunately, the tests do occasionally rely on the logs being formatted in the old way. Are you up for updating some tests @bachsh?

[bachsh]

Yes @jsignell I definitely want to update the relevant tests! Can you help me figure out what they are? The failures in the PR seem irrelevant to the logs structure (but I may be reading it wrong) and on my local setup I'm getting different failures.

[jsignell]

I'd recommend trying to get tests passing locally on master, then if once that is working, try to get them passing locally on your branch.

[jrbourbeau]

Just checking in @bachsh, are you blocked on anything at the moment?

The following set of changes should update the tests to pass

diff --git a/distributed/cli/tests/test_dask_scheduler.py b/distributed/cli/tests/test_dask_scheduler.py
index 543d4300..695c76c6 100644
--- a/distributed/cli/tests/test_dask_scheduler.py
+++ b/distributed/cli/tests/test_dask_scheduler.py
@@ -237,11 +237,13 @@ def test_dashboard_port_zero(loop):
         with popen(["dask-scheduler", "--dashboard-address", ":0"]) as proc:
             count = 0
             while count < 1:
-                line = proc.stderr.readline()
-                if b"dashboard" in line.lower():
+                line = proc.stderr.readline().decode("utf8")
+                if "dashboard" in line.lower():
                     sleep(0.01)
                     count += 1
-                    assert b":0" not in line
+                    # Remove timestamp from logging line which may contain ":0"
+                    line = " - ".join(line.split(" - ")[1:])
+                    assert ":0" not in line
 
 
 PRELOAD_TEXT = """
diff --git a/distributed/tests/test_config.py b/distributed/tests/test_config.py
index 74b57b1f..5b11f183 100644
--- a/distributed/tests/test_config.py
+++ b/distributed/tests/test_config.py
@@ -91,10 +91,12 @@ def test_logging_default():
         foreign_log = foreign_log.getvalue().splitlines()
 
         # distributed log is configured at INFO level by default
-        assert distributed_log == [
+        expected_log = [
             "distributed - INFO - 2: info",
             "distributed.foo.bar - INFO - 3: info",
         ]
+        for result, expected in zip(distributed_log, expected_log):
+            assert expected in result
 
         # foreign logs should be unaffected by distributed's logging
         # configuration.  They get the default ERROR level from logging.
@@ -138,11 +140,12 @@ def test_logging_simple_under_distributed():
                 dfb.error("3: error")
 
             distributed_log = distributed_log.getvalue().splitlines()
-
-            assert distributed_log == [
+            expected_log = [
                 "distributed.foo - INFO - 1: info",
                 "distributed.foo.bar - ERROR - 3: error",
-                ], (dask.config.config, distributed_log)
+            ]
+            for result, expected in zip(distributed_log, expected_log):
+                assert expected in result, (dask.config.config, result, expected)
             """
 
         subprocess.check_call([sys.executable, "-c", code])
@@ -173,11 +176,12 @@ def test_logging_simple():
                 dfb.error("3: error")
 
             distributed_log = distributed_log.getvalue().splitlines()
-
-            assert distributed_log == [
+            expected_log = [
                 "distributed.foo - INFO - 1: info",
                 "distributed.foo.bar - ERROR - 3: error",
-                ], (dask.config.config, distributed_log)
+            ]
+            for result, expected in zip(distributed_log, expected_log):
+                assert expected in result, (dask.config.config, result, expected)
             """
 
         subprocess.check_call([sys.executable, "-c", code])

[bachsh]

Thanks a lot, @jrbourbeau . Unfortunately I ran into a very stressful period at my day job I really hope to make time for taking care of this sometime in the next 3 weeks.

[bachsh]

@jrbourbeau thanks for the help with changing the tests.
The tests pass on my station (working on a Mac) but in the CI (Windows) I'm getting timeout errors I can't replicate on my station, and don't know how to fix. Any leads?

[bachsh]

Ping @jsignell @jrbourbeau .
I could use some help here with getting the CI tests passing

[jsignell]

Sorry this slipped off my radar. Let's merge with master and see if the CI tests pass 🤞

[jsignell]

@bachsh would you be able to merge dask/distributed master? I thought I'd be able to do it for you, but I don't have the right permissions.

[bachsh]

@jsignell, I can't. Only those with write access can merge; we will have to wait for @jrbourbeau

[jsignell]

Only those with write access can merge

Sorry that was unclear. I meant merge master into your fork:branch.

[bachsh]

Sorry that was unclear. I meant merge master into your fork:branch.

Oops, I'm sorry I should've understood that was your intention; you're suggesting that this test might have been fixed in the main branch. Makes sense. Waiting for the tests now

[bachsh]

@jsignell , pulling from master didn't do the trick. We get the same timeout failure. Any lead?

[jsignell]

Yeah just saw that :( windows bugs are hard to track down. I'll defer to @jrbourbeau

[bachsh]

Ping @jrbourbeau, can you help figure out why CI tests fail? All the test pass properly on my station (Mac)

[bachsh]

hey @jsignell can you approve running the workflows so we can see if tests pass?

[jsignell]

This shouldn't be necessary.

[jsignell]

This is looking pretty good, just one last comment. Note that the tests depend on pytest-asyncio which you might need to install in your env.

[hendrikmakait]

Superseded by #5897