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

Fix log message duplication #6766

Merged
merged 1 commit into from
Sep 6, 2023
Merged

Conversation

SpecLad
Copy link
Contributor

@SpecLad SpecLad commented Aug 29, 2023

Motivation and context

There are two independent problems that cause some log messages to be printed twice:

  • In the CVAT logging configuration, we attach a console handler to the cvat and django loggers. However, when any library[1] used by CVAT uses one of the top-level logging functions (e.g. logging.info), then it will cause the root logger to get autoconfigured with another console handler. Since cvat and django are configured to propagate events to the ancestor logger's handlers, those events are passed to two console handlers, so they are printed twice.

    Fix it by moving our handlers to the root logger. If the root logger has handlers, it will no longer get autoconfigured when top-level logging functions are invoked; so there will only be one console handler in the logger chain.

    An alternative would be to configure the root logger with a NullHandler (which will also disable autoconfiguration), but this will suppress all logs that are coming from places other than Django and CVAT, which seems undesirable.

  • The supervisord config file for the server redirects the server's stdout to supervisord's stdout. However, supervisord already displays the stdout of all child processes due to the loglevel=debug setting. So all stdout messages of the server are displayed twice.

    Fix it by removing the redirection.

[1] Specifically, Datumaro does this. It could probably be fixed, but that wouldn't fix the root problem, which is the duplicate console handler.

How has this been tested?

Checklist

  • I submit my changes into the develop branch
  • I have added a description of my changes into the CHANGELOG file
  • [ ] I have updated the documentation accordingly
  • [ ] I have added tests to cover my changes
  • [ ] I have linked related issues (see GitHub docs)
  • [ ] I have increased versions of npm packages if it is necessary
    (cvat-canvas,
    cvat-core,
    cvat-data and
    cvat-ui)

License

  • I submit my code changes under the same MIT License that covers the project.
    Feel free to contact the maintainers if that's a concern.

@codecov
Copy link

codecov bot commented Aug 29, 2023

Codecov Report

Merging #6766 (ca4164d) into develop (84c0816) will decrease coverage by 0.01%.
The diff coverage is n/a.

@@             Coverage Diff             @@
##           develop    #6766      +/-   ##
===========================================
- Coverage    82.46%   82.45%   -0.01%     
===========================================
  Files          366      366              
  Lines        39761    39761              
  Branches      3545     3545              
===========================================
- Hits         32787    32784       -3     
- Misses        6974     6977       +3     
Components Coverage Δ
cvat-ui 77.41% <ø> (-0.02%) ⬇️
cvat-server 86.87% <ø> (ø)

There are two independent problems that cause some log messages to be
printed twice:

* In the CVAT logging configuration, we attach a console handler to the
  `cvat.server` and `django` loggers. However, when any library[1] used by
  CVAT uses one of the top-level `logging` functions (e.g. `logging.info`),
  then it will cause the root logger to get autoconfigured with another
  console handler. Since `cvat.server` and `django` are configured to
  propagate events to the ancestor logger's handlers, those events are
  passed to _two_ console handlers, so they are printed twice.

  Fix it by moving our handlers to the root logger. If the root logger has
  handlers, it will no longer get autoconfigured when top-level `logging`
  functions are invoked; so there will only be one console handler in the
  logger chain.

  An alternative would be to configure the root logger with a `NullHandler`
  (which will also disable autoconfiguration), but this will suppress all
  logs that are coming from places other than Django and CVAT, which seems
  undesirable.

* The supervisord config file for the server redirects the server's stdout
  to supervisord's stdout. However, supervisord already displays the stdout
  of all child processes due to the `loglevel=debug` setting. So all stdout
  messages of the server are displayed twice.

  Fix it by removing the redirection.

[1] Specifically, Datumaro does this. It could probably be fixed, but that
    wouldn't fix the root problem, which is the duplicate console handler.
@SpecLad
Copy link
Contributor Author

SpecLad commented Sep 6, 2023

@azhavoro Could you review this?

@azhavoro
Copy link
Contributor

azhavoro commented Sep 6, 2023

LGTM

@SpecLad SpecLad merged commit 92f1372 into cvat-ai:develop Sep 6, 2023
32 checks passed
@SpecLad SpecLad deleted the duplicate-logs branch September 6, 2023 13:33
@azhavoro azhavoro mentioned this pull request Sep 6, 2023
nmanovic added a commit that referenced this pull request Sep 6, 2023
### Added

- Gamma correcton filter (<#6771>)
- Introduced the feature to hide or show objects in review mode (<#6808>)

### Changed

- \[Helm\] Database migrations are now executed as a separate job,
  rather than in the server pod, to mitigate the risk of data
  corruption when using multiple server replicas
  (<#6780>)
- Clicking multiple times on icons in the left
  sidebar now toggles the corresponding popovers open and closed
  (<#6817>)
- Transitioned to using KeyDB with FLASH for data
  chunk caching, replacing diskcache (<#6773>)

### Removed

- Removed outdated use of hostnames when accessing Git, OpenCV, or analytics via the UI (<#6799>)
- Removed the Feedback/Share component (<#6805>)

### Fixed

- Resolved the issue of the canvas zooming while scrolling
  through the comments list in an issue (<#6758>)
- Addressed the bug that allowed for multiple issue
  creations upon initial submission (<#6758>)
- Fixed the issue of running deep learning models on
  non-JPEG compressed TIFF images (<#6789>)
- Adjusted padding on the tasks, projects, and models pages (<#6778>)
- Corrected hotkey handlers to avoid overriding default behavior when modal windows are open
  (<#6800>)
- Resolved the need to move the mouse to activate
  brush or eraser effects; a single click is now sufficient (<#6800>)
- Fixed a memory leak issue in the logging system (<#6804>)
- Addressed a race condition that occurred during the initial creation of `secret_key.py`
  (<#6775>)
- Eliminated duplicate log entries generated by the CVAT server
  (<#6766>)
mikhail-treskin pushed a commit to retailnext/cvat that referenced this pull request Oct 25, 2023
There are two independent problems that cause some log messages to be
printed twice:

* In the CVAT logging configuration, we attach a console handler to the
  `cvat` and `django` loggers. However, when any library[1] used by CVAT
  uses one of the top-level `logging` functions (e.g. `logging.info`),
  then it will cause the root logger to get autoconfigured with another
  console handler. Since `cvat` and `django` are configured to propagate
  events to the ancestor logger's handlers, those events are passed to
  _two_ console handlers, so they are printed twice.

  Fix it by moving our handlers to the root logger. If the root logger has
  handlers, it will no longer get autoconfigured when top-level `logging`
  functions are invoked; so there will only be one console handler in the
  logger chain.

  An alternative would be to configure the root logger with a
  `NullHandler` (which will also disable autoconfiguration), but this will
  suppress all logs that are coming from places other than Django and
  CVAT, which seems undesirable.

* The supervisord config file for the server redirects the server's
  stdout to supervisord's stdout. However, supervisord already displays
  the stdout of all child processes due to the `loglevel=debug` setting.
  So all stdout messages of the server are displayed twice.

  Fix it by removing the redirection.

[1] Specifically, Datumaro does this. It could probably be fixed, but
that wouldn't fix the root problem, which is the duplicate console
handler.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants