send task_received signal before receive log #8697

Niccolum · 2023-12-06T10:13:12Z

Description

I want to receive task_received signal before info(_app_trace.LOG_RECEIVED, context, extra={'data': context}) for add some context to log

codecov · 2023-12-06T10:53:53Z

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 81.25%. Comparing base (c3dac19) to head (8053b9c).

❗ Current head 8053b9c differs from pull request most recent head a295c50. Consider uploading reports for the commit a295c50 to get more accurate results

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #8697      +/-   ##
==========================================
- Coverage   81.26%   81.25%   -0.02%     
==========================================
  Files         150      149       -1     
  Lines       18686    18553     -133     
  Branches     3193     3166      -27     
==========================================
- Hits        15186    15075     -111     
+ Misses       3209     3191      -18     
+ Partials      291      287       -4

Flag	Coverage Δ
unittests	`81.23% <100.00%> (-0.02%)`	⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

auvipy

we need more context here and preferably some unit / integration tests for the suggested change

Niccolum · 2023-12-07T06:25:56Z

@auvipy hello!

My point is to send receive logs after task_received signal.

For me it's important, because i sent to celery some context for logs.
To be more specific, I pass a trace token there to track how that task was called.
So, i pass context through signals and task_received is that signal, which i need, i think.

If you tell me what tests are best to write for this, then I will try to attach them

50-Course

👍🏼 to @auvipy request to help resolve concerns, thank you.

celery/worker/strategy.py

Niccolum · 2023-12-12T09:30:46Z

@50-Course @auvipy hello!

I wrote a unit test to cover the flow change

Please ask me if you need anything else.

UPD: No idea, why tests with pypy failed

Nusnus · 2023-12-12T10:06:36Z

UPD: No idea, why tests with pypy failed

Not related to this PR.
I've restarted the CI.

auvipy · 2023-12-12T14:30:31Z

Will check after the office hour.

Nusnus · 2023-12-12T15:07:12Z

Will check after the office hour.

I've noticed GitHub Actions in general is having troubles since the last few hours, well, much more than usual (jobs fail before the code/tests actually run).

FYI @auvipy

Niccolum · 2023-12-18T14:32:53Z

Hello, @auvipy @50-Course

If i can help for this, just ask me how.

Thanks for your time and effort!

50-Course · 2023-12-19T06:57:50Z

Hello again, @Niccolum, by my understanding this has nothing to do with your MR. I think the PR has achieved it's scope and success criteria given the tests and non-breaking changes.

The failing pipeline, Celery/Unit (pypy-310), is however, most likely caused by setuptools.

If you take a look at the last function on the stacktrace, you'd figure:

The error message, indicates that there is a problem with the setuptools.build_meta_legacy function. This function is used to generate metadata for Python packages.

Obviously, a problem with the tox configuration. If @auvipy or @Nusnus could help ensure that the tox.ini file is correct - that should fix it all up.

Nonetheless, the PR is as good as merged 👍🏼

auvipy

I re run the failed job to trigger Integrations tests

t/unit/worker/test_strategy.py

Niccolum · 2024-01-27T13:23:38Z

Hello everyone.
Do you need any help with pypy build? Or this problem is resolved?

@Nusnus @auvipy @50-Course

Nusnus · 2024-01-27T19:43:14Z

@Niccolum

Hello everyone. Do you need any help with pypy build? Or this problem is resolved?

@Nusnus @auvipy @50-Course

TBH I am not sure what happened, but the latest main CI run passed 100% so I suggest a rebase & solving conflicts should get it working. If it doesn't, then it’s probaby something in this PR.

Let’s update the PR first so we can direct our focus more efficiently.

50-Course · 2024-01-28T00:38:36Z

Hi @Niccolum,

Can I proffer you try out @Nusnus suggestions? At the very least, the specific change might just be from the runner/tox at the time.

That said, I would have to take one clean swoop at the commits (few before this, this and few after this) again

Niccolum · 2024-01-28T05:42:51Z

@50-Course Hello)

Yes, you can, why not)
I'll check and return later

Niccolum · 2024-01-29T06:26:42Z

@Nusnus @50-Course hello!

Pull to actual main state and run
tox -e pypy-3

with result

pypy-3: OK (107.46 seconds)
  congratulations :) (108.70 seconds)

Maybe you can run pipeline again?)
Thanks!

50-Course · 2024-01-29T08:44:17Z

Could you unblock me here @Niccolum @Nusnus, I kind of lost track, that should be the PR itself here?

Approving once I get this one right :)

Niccolum · 2024-01-29T09:01:10Z

Could you unblock me here @Niccolum @Nusnus, I kind of lost track, that should be the PR itself here?

@50-Course
Sorry, I don't know.

UPD: As i see - celery jobs fail because of lost codecov token

Nusnus · 2024-01-29T09:03:16Z

Could you unblock me here @Niccolum @Nusnus, I kind of lost track, that should be the PR itself here?

@50-Course
Sorry, I don't know.

UPD: As i see - celery jobs fail because of lost codecov token

I'll give codecov a few minutes to calm down and rerun.
It's a known issue, don't worry.

It's due to many PRs running at the same time (right now)

50-Course · 2024-01-29T09:18:00Z

I so happen to spin up a proposed solution, can't run workflow from the cli so i added a ticket for that would require separate implementation: #8822

Once approved, I'd send in a patch!

Niccolum · 2024-01-29T09:33:30Z

As i see - on pypy

FAILED t/unit/worker/test_strategy.py::test_default_strategy_proto1::test_when_logging_disabled
FAILED t/unit/worker/test_strategy.py::test_default_strategy_proto1__no_utc::test_when_logging_disabled
FAILED t/unit/worker/test_strategy.py::test_custom_request_for_default_strategy::test_when_logging_disabled

Nothing for other builds...

How is this possible?

Niccolum · 2024-01-30T06:48:45Z

locally, i see
% tox -e pypy-3-unit

t/unit/worker/test_strategy.py::test_default_strategy_proto2::test_when_logging_disabled PASSED
t/unit/worker/test_strategy.py::test_default_strategy_proto1::test_when_logging_disabled PASSED
t/unit/worker/test_strategy.py::test_default_strategy_proto1__no_utc::test_when_logging_disabled PASSED
t/unit/worker/test_strategy.py::test_custom_request_for_default_strategy::test_when_logging_disabled PASSED

Do you have any ideas?
@50-Course @Nusnus @auvipy

Maybe we can try re-run pypy job?

50-Course · 2024-01-30T07:08:59Z

@Niccolum, just got in by workspace. Quick question, the was no diff in the affected files? getting to it, once my system comes up.

50-Course · 2024-01-30T07:16:16Z

If this passes, we'd just have to re-push these files off to VCS. btw, i can't seem to re-run workflow on my end... I should turn in the PR for #8822 to help in that regard.

50-Course · 2024-01-30T08:03:12Z

@Niccolum, Please update it from your end.. can't update the commits from my end - I'd have to reach out to @Nusnus @auvipy

With that, this is good as merged 🚀 @Nusnus please make one quick sweep, and if anything, I'd be back in couple of minutes.

That said, I'll be waiting for the update. Well done @Niccolum, and thank you for making this patch 🤝

Niccolum · 2024-01-30T09:31:53Z

@50-Course added your one-line patch to my PR
Thanks for your help!

Niccolum · 2024-01-30T09:38:41Z

@50-Course i remove coverage flags and now it falls because no coverage files for codecov.

Sooo.... What can we do now?

UPD: these three tests from #8697 (comment) still failed...

Niccolum · 2024-01-30T09:47:31Z

I revert my latest commit with tox.ini config changing

Nusnus · 2024-01-30T09:58:47Z

I was just commenting on it hahaha

Nusnus · 2024-01-30T10:00:54Z

All of the recent commits “choke” the GitHub CI.
I’ll kill the previous runs so the new changes can start immediately.
Few sec

EDIT: There’s another PR already using the CI workers to 100%. Let’s take a short break and come back to see where we are in 30m.

Nusnus · 2024-01-30T10:26:02Z

2024-01-30T10:16:56.0775343Z =================================== FAILURES ===================================
2024-01-30T10:16:56.0792182Z ___________ test_default_strategy_proto1.test_when_logging_disabled ____________
2024-01-30T10:16:56.0794508Z 
2024-01-30T10:16:56.0795055Z self = <t.unit.worker.test_strategy.test_default_strategy_proto1 object at 0x00007fd9f8dac8e0>
2024-01-30T10:16:56.0796526Z caplog = <_pytest.logging.LogCaptureFixture object at 0x0000000032b90090>
2024-01-30T10:16:56.0797102Z 
2024-01-30T10:16:56.0797329Z     def test_when_logging_disabled(self, caplog):
2024-01-30T10:16:56.0797933Z         # Capture logs at any level above `NOTSET`
2024-01-30T10:16:56.0798677Z         caplog.set_level(logging.NOTSET + 1, logger="celery.worker.strategy")
2024-01-30T10:16:56.0799776Z         with patch('celery.worker.strategy.logger') as logger:
2024-01-30T10:16:56.0800620Z             logger.isEnabledFor.return_value = False
2024-01-30T10:16:56.0801611Z             with self._context(self.add.s(2, 2)) as C:
2024-01-30T10:16:56.0802306Z                 C()
2024-01-30T10:16:56.0802783Z >       assert not caplog.records
2024-01-30T10:16:56.0804472Z E       assert not [<LogRecord: celery.utils.dispatch.signal, 40, /home/runner/work/celery/celery/celery/utils/dispatch/signal.py, 280, "Signal handler %r raised: %r">]
2024-01-30T10:16:56.0807768Z E        +  where [<LogRecord: celery.utils.dispatch.signal, 40, /home/runner/work/celery/celery/celery/utils/dispatch/signal.py, 280, "Signal handler %r raised: %r">] = <_pytest.logging.LogCaptureFixture object at 0x0000000032b90090>.records
2024-01-30T10:16:56.0809695Z 
2024-01-30T10:16:56.0809961Z t/unit/worker/test_strategy.py:154: AssertionError

Nusnus · 2024-01-30T10:33:58Z

Long shot - but can you try updating the PR to use pytest v8.0.0?
There’s a pending PR for upgrading, I wonder if it may help here before we move forward with the upgrade.

But it’s a very long shot, so let’s not get our hopes too high :)

Niccolum · 2024-01-30T10:39:31Z

@Nusnus Have you any ideas why is fails only on pypy?

P.S. i can try to use pytest 8.0.0, of course. I'll give you feedback later

Nusnus · 2024-01-30T10:42:51Z

@Nusnus Have you any ideas why is fails only only on pypy?

P.S. i can try to use pytest 8.0.0, of course. I'll give you feedback later

My best guess is a dependency that was upgraded internally (maybe a dep of a dep), that changed something.
That’s why I offered v8.0.0 as a long shot.

But @auvipy just merged main so let’s give it a shot first and then make the attempt with v8.0.0.

🤞

50-Course · 2024-01-30T11:15:38Z

@Niccolum best bet right now, is there's a transitive dependency issue somewhere down the line, and that is related to pytest-cov - did we have any plugin with the name helpconfig? 🤔

I should do a quick grep project-wide

Niccolum · 2024-01-30T11:17:53Z

@50-Course as I see, it's best bet for local tox running. Not for resolve current problem

50-Course · 2024-01-30T11:29:16Z

Ha interesting it is a core dependency, from the pytest module:

~../site-packages/_pytest/config/init.py

# Plugins that cannot be disabled via "-p no:X" currently.
essential_plugins = (
    "mark",
    "main",
    "runner",
    "fixtures",
    "helpconfig",  # Provides -p.
)

Niccolum · 2024-01-30T13:27:11Z

@Nusnus locally runs successful with
tox -e pypy-3-unit like in past, but with pytest-8.0.0
also added local name for pypy in tox config (if i run tox local - test-ci-default.txt didn't install)

Can you run pipeline again?

============================== 3245 passed, 11 skipped, 3 xfailed, 59 warnings, 28910 subtests passed in 175.47s (0:02:55) ==============================
.pkg: _exit> python /Users/n.vidov/Desktop/projects/github/celery/.tox/.tox/lib/python3.10/site-packages/pyproject_api/_backend.py True setuptools.build_meta __legacy__
  pypy-3-unit: OK (268.48=setup[83.63]+cmd[184.85] seconds)
  congratulations :) (272.16 seconds)

Niccolum · 2024-01-30T13:57:02Z

@50-Course i think, i resolve problem with cov while tox running locally with one-line fix in tox config =) As i understand - in gh - pypy names pypy3, but locally it's - pypy-3

Nusnus · 2024-01-30T15:53:07Z

Thanks - let's see if it works!

Niccolum · 2024-01-30T16:08:55Z

@Nusnus No, still unsuccessful only on pypy.
Still these three tests
:'(

Niccolum · 2024-01-31T07:59:45Z

@Nusnus @auvipy @50-Course

Do you have any ideas?

Nusnus · 2024-01-31T12:26:10Z

@Nusnus @auvipy @50-Course

Do you have any ideas?

When I hit a wall, I usually try to review my approach again and try from a different angle.
In this case, it seems we’ll have to fallback to the oldschool method of commenting out lines until we find what’s causing it.

I’d suggest:

Revert any possibly unrelated change (e.g tox.ini, pytest version etc.).
Remove your test (just add @pytest.mark.skip)
I’ll review the PR again and place comments where I believe you could start cutting out stuff.

If you’re up for it, I am willing to be “on watch” for CI approvals etc. @Niccolum

Niccolum · 2024-01-31T12:28:39Z

@Nusnus Of course I agree. Thank you very much. Then, not today, I’ll throw out these options

Nusnus

See my suggestions @Niccolum.

Remember, we’re just messing up with the code to remove noise and trying to pinpoint the reason it fails (in the CI only if I understand correctly).

Nusnus · 2024-01-31T12:26:49Z

CONTRIBUTORS.txt

This change obviously doesn’t affect anything so we can move on

Nusnus · 2024-01-31T12:27:05Z

tox.ini

@@ -33,7 +33,7 @@ deps=

    3.8,3.9,3.10,3.11,3.12: -r{toxinidir}/requirements/test-ci-default.txt
    3.8,3.9,3.10,3.11,3.12: -r{toxinidir}/requirements/docs.txt
-    pypy3: -r{toxinidir}/requirements/test-ci-default.txt


Revert this

Nusnus · 2024-01-31T12:27:15Z

requirements/test.txt

@@ -1,4 +1,4 @@
-pytest==7.4.4


Revert this

Nusnus · 2024-01-31T12:27:42Z

t/unit/worker/test_strategy.py

@@ -234,6 +234,35 @@ def test_signal_task_received(self):
                                             request=ANY,
                                             signal=signals.task_received)

+    def test_log_task_received_meta(self, caplog):


add @pytest.mark.skip (double-check me for the syntax)

Nusnus · 2024-01-31T12:33:31Z

celery/worker/strategy.py

@@ -148,17 +148,7 @@ def task_message_handler(message, body, ack, reject, callbacks,
            eventer=eventer, task=task, connection_errors=connection_errors,
            body=body, headers=headers, decoded=decoded, utc=utc,
        )
-        if _does_info:


Just for the sake of being “the first iteration of messing up the code”, try to get all of this code back here, except the info call itself.

Nusnus · 2024-01-31T12:35:07Z

celery/worker/strategy.py

+                'kwargs': req.kwargsrepr,
+                'eta': req.eta,
+            }
+            info(_app_trace.LOG_RECEIVED, context, extra={'data': context})


leave just the if … info().

The purpose is mainly to reduce the changed lines. This is just to remove noise so we can, step by step, improve our focus on the changes that caused it.

Nusnus · 2024-01-31T12:39:28Z

Also, just for the sake of it, rebase on main when you push the next changes.

Niccolum changed the title ~~send task_received sygnal before receive log~~ send task_received signal before receive log Dec 6, 2023

Niccolum force-pushed the main branch 2 times, most recently from c2530bc to f3fad4e Compare December 6, 2023 10:27

auvipy requested changes Dec 6, 2023

View reviewed changes

50-Course suggested changes Dec 7, 2023

View reviewed changes

celery/worker/strategy.py Show resolved Hide resolved

send task_received signal before receive log

1a5af22

Niccolum force-pushed the main branch from f3fad4e to 1a5af22 Compare December 12, 2023 09:28

auvipy requested changes Dec 19, 2023

View reviewed changes

auvipy requested changes Dec 31, 2023

View reviewed changes

t/unit/worker/test_strategy.py Show resolved Hide resolved

Niccolum force-pushed the main branch from 8dddc74 to 3ab1035 Compare January 30, 2024 09:31

Niccolum force-pushed the main branch from 3ab1035 to bebb5cd Compare January 30, 2024 09:46

Niccolum force-pushed the main branch from bebb5cd to 5a5dd8b Compare January 30, 2024 09:57

Niccolum force-pushed the main branch from b3e0180 to 16fa66b Compare January 30, 2024 13:17

send task_received signal before receive log

7d40f18

Niccolum force-pushed the main branch from 16fa66b to 7d40f18 Compare January 30, 2024 13:23

Nusnus reviewed Jan 31, 2024

View reviewed changes

auvipy added 2 commits February 6, 2024 20:50

Merge branch 'main' into main

8053b9c

Merge branch 'main' into main

a295c50

send task_received signal before receive log #8697

Are you sure you want to change the base?

send task_received signal before receive log #8697

Conversation

Niccolum commented Dec 6, 2023

Description

codecov bot commented Dec 6, 2023 • edited

Codecov Report

auvipy left a comment

Choose a reason for hiding this comment

Niccolum commented Dec 7, 2023 • edited

50-Course left a comment

Choose a reason for hiding this comment

Niccolum commented Dec 12, 2023 • edited

Nusnus commented Dec 12, 2023

auvipy commented Dec 12, 2023

Nusnus commented Dec 12, 2023

Niccolum commented Dec 18, 2023

50-Course commented Dec 19, 2023

auvipy left a comment

Choose a reason for hiding this comment

Niccolum commented Jan 27, 2024

Nusnus commented Jan 27, 2024

50-Course commented Jan 28, 2024

Niccolum commented Jan 28, 2024 • edited

Niccolum commented Jan 29, 2024

50-Course commented Jan 29, 2024 • edited

Niccolum commented Jan 29, 2024

Nusnus commented Jan 29, 2024 • edited

50-Course commented Jan 29, 2024 • edited

Niccolum commented Jan 29, 2024 • edited

Niccolum commented Jan 30, 2024 • edited

50-Course commented Jan 30, 2024

50-Course commented Jan 30, 2024

50-Course commented Jan 30, 2024 • edited

Niccolum commented Jan 30, 2024 • edited

Niccolum commented Jan 30, 2024 • edited

Niccolum commented Jan 30, 2024

Nusnus commented Jan 30, 2024

Nusnus commented Jan 30, 2024 • edited

Nusnus commented Jan 30, 2024

Nusnus commented Jan 30, 2024

Niccolum commented Jan 30, 2024 • edited

Nusnus commented Jan 30, 2024

50-Course commented Jan 30, 2024

Niccolum commented Jan 30, 2024

50-Course commented Jan 30, 2024

Niccolum commented Jan 30, 2024 • edited

Niccolum commented Jan 30, 2024

Nusnus commented Jan 30, 2024

Niccolum commented Jan 30, 2024 • edited

Niccolum commented Jan 31, 2024

Nusnus commented Jan 31, 2024

Niccolum commented Jan 31, 2024

Nusnus left a comment

Choose a reason for hiding this comment

Nusnus Jan 31, 2024

Choose a reason for hiding this comment

Nusnus Jan 31, 2024

Choose a reason for hiding this comment

Nusnus Jan 31, 2024

Choose a reason for hiding this comment

Nusnus Jan 31, 2024

Choose a reason for hiding this comment

Nusnus Jan 31, 2024

Choose a reason for hiding this comment

Nusnus Jan 31, 2024

Choose a reason for hiding this comment

Nusnus commented Jan 31, 2024

codecov bot commented Dec 6, 2023 •

edited

Niccolum commented Dec 7, 2023 •

edited

Niccolum commented Dec 12, 2023 •

edited

Niccolum commented Jan 28, 2024 •

edited

50-Course commented Jan 29, 2024 •

edited

Nusnus commented Jan 29, 2024 •

edited

50-Course commented Jan 29, 2024 •

edited

Niccolum commented Jan 29, 2024 •

edited

Niccolum commented Jan 30, 2024 •

edited

50-Course commented Jan 30, 2024 •

edited

Niccolum commented Jan 30, 2024 •

edited

Niccolum commented Jan 30, 2024 •

edited

Nusnus commented Jan 30, 2024 •

edited

Niccolum commented Jan 30, 2024 •

edited

Niccolum commented Jan 30, 2024 •

edited

Niccolum commented Jan 30, 2024 •

edited