Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

✨Adds timestamps to sidecars (dynamic and computational) #2817

Closed
wants to merge 5 commits into from

Conversation

GitHK
Copy link
Contributor

@GitHK GitHK commented Feb 10, 2022

What do these changes do?

To allow users to more easily figure out what is happening with the services, timestamps were added to the logs coming from sidecars.

Related issue/s

How to test

Checklist

@GitHK GitHK added this to the R.Schumann milestone Feb 10, 2022
@GitHK GitHK self-assigned this Feb 10, 2022
@codecov
Copy link

codecov bot commented Feb 10, 2022

Codecov Report

Merging #2817 (641db08) into master (d8159e2) will decrease coverage by 0.0%.
The diff coverage is 88.8%.

Impacted file tree graph

@@           Coverage Diff            @@
##           master   #2817     +/-   ##
========================================
- Coverage    78.9%   78.9%   -0.1%     
========================================
  Files         671     671             
  Lines       27290   27296      +6     
  Branches     3148    3148             
========================================
- Hits        21542   21541      -1     
- Misses       4992    4996      +4     
- Partials      756     759      +3     
Flag Coverage Δ
integrationtests 65.9% <ø> (-0.1%) ⬇️
unittests 74.4% <88.8%> (-0.1%) ⬇️

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

Impacted Files Coverage Δ
...c/simcore_service_dynamic_sidecar/core/rabbitmq.py 85.7% <88.8%> (-0.2%) ⬇️
...rvice-library/src/servicelib/common_aiopg_utils.py 88.2% <0.0%> (-8.9%) ⬇️
...simcore_service_webserver/projects/project_lock.py 94.7% <0.0%> (-5.3%) ⬇️
...ore_service_director_v2/api/routes/computations.py 80.1% <0.0%> (-2.6%) ⬇️
...simcore_service_director_v2/modules/dask_client.py 81.9% <0.0%> (-0.7%) ⬇️
.../director/src/simcore_service_director/producer.py 62.7% <0.0%> (+0.4%) ⬆️

for message in log_msg:
await self._channel_queues[self.CHANNEL_LOG].put(message)
with_timestamp = f"{time_string} {message}"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

THOUGHT:
When you add something in a log, i would always make sure it can be parsed back easily and reliably. e.g. the front end might want to add that in an extra column. Your test below clearly suggests otherwise

For instance #2157 we show some ideas on how to achieve that.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggestion:

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@pcrespov where you trying to add an example above?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My idea here was to avoid a mess in the UI and make it as minimalistic as possible.

services/dynamic-sidecar/tests/unit/test_core_rabbitmq.py Outdated Show resolved Hide resolved
@GitHK GitHK requested a review from pcrespov February 11, 2022 10:41
def mock_datetime_utc_now(
monkeypatch: MonkeyPatch,
) -> datetime.date:
# Note: since datetime is unmutable, best approach is to
Copy link
Member

@pcrespov pcrespov Feb 11, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Are you sure about this? Are you by any chance trying to datatime instead of datetime?
Check this
https://stackoverflow.com/questions/43799206/python-how-do-i-mock-datetime-utcnow

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So I finally managed to patch the object with something inspire form https://stackoverflow.com/a/51213128/2855718
You need to wrap the class in a mock and than you can access it's methods.

But I got stopped by tenacity, which apparently uses datetime to compute some metric.

Since I don't want to spend to much time on it. this current implementation is the best I have.

Copy link
Member

@pcrespov pcrespov left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As discussed, I think that the log mechanism needs to be revisited (It would be good to get @sanderegg input on that as well) but if this fixes the current needs, go ahead.

@GitHK GitHK requested a review from sanderegg February 11, 2022 14:40
@@ -168,8 +174,10 @@ async def post_log_message(self, log_msg: Union[str, List[str]]) -> None:
if isinstance(log_msg, str):
log_msg = [log_msg]

time_string = _get_utc_now().strftime(LOG_DATETIME_FORMAT)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

so if I get it correctly you actually add the timestamp when logging to rabbitMQ right?
in the dask-sidecar I already get the timestamps from the docker container directly, see here if possible which I think you can.
I am missing a timestamp for messages not from the container, that is right, but I can see that if we need to debug it is probably easier if the timestamp is the same as what we would see in graylog.

Shall we go for adding a timestamp only if it is missing? or having a rabbitMQ timestamp and a container timestamp? I mean the message in rabbitMQ is pretty flexible. I think we can pass a json with several fields. what do you think?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree with fetching the timestamps from the container and injecting it where missing.

Currently the timestamp is part of the message, as also it is part of the message the source.

If you'd like to inject other files, at this point we might want to transform the LoggerRabbitMessage from sending a list of strings containing the messages to the logger to sending a json. At that point the fronted will format the logs.
Is something like this what you had in mind? Not sure if doing this would push too much work on the frontend.

@GitHK GitHK requested a review from sanderegg February 14, 2022 11:44
@pcrespov pcrespov removed this from the R.Schumann milestone Mar 14, 2022
@pcrespov pcrespov added this to the E.Shackleton milestone Mar 24, 2022
@sanderegg sanderegg removed their request for review August 2, 2022 05:55
@pcrespov pcrespov modified the milestones: Katherine Switzer, Athena Nov 23, 2022
@pcrespov pcrespov removed this from the Athena milestone Dec 14, 2022
@pcrespov pcrespov added this to the Zefram Cochrane milestone Dec 14, 2022
@GitHK
Copy link
Contributor Author

GitHK commented Feb 6, 2023

outdated, issue was already closed

@GitHK GitHK closed this Feb 6, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
a:dynamic-sidecar dynamic-sidecar service
Projects
None yet
Development

Successfully merging this pull request may close these issues.

timestamps in the logger
3 participants