search

iiuni / projektzapisy

System Zapisów na zajęcia w Instytucie Informatyki Uniwersytetu Wrocławskiego
https://zapisy.ii.uni.wroc.pl
30 stars 10 forks source link

#1435 Naprawa zduplikowanych logów w pliku djangoproject.log #1599

Closed Dawid-Sroka closed 8 months ago

Dawid-Sroka commented 10 months ago

Konfiguracja loggerów w pliku settings.py była obarczona wadą polegającą na tym, że loggery podrzędne propagowały swoje wiadomości do root logger'a. W efekcie większość wiadomości w pliku djangoproject.log była zduplikowana a dodatkowo były tam dodawane logi, które z założenia miały trafiać do pliku rqworker.log.

Zgodnie z sugestią z Issue, dodałem własności 'propagate': False do każdego z loggerów i to zdaje się rozwiązać problem.

Przedstawiam porównanie wiadomości w logach przed i po dodaniu własności propagacji: Przed Przykładowe logi, które występowały w pliku djangoproject.log na mojej maszynie, kiedy własność propagacji nie była włączona:

2023-11-12 19:12:13,909 [Thread-15   ] [INFO ] [django.server       ]  "GET /notifications/get HTTP/1.1" 304 0
2023-11-12 19:12:13,909 [Thread-15   ] [INFO ] [django.server       ]  "GET /notifications/get HTTP/1.1" 304 0
2023-11-12 19:12:19,872 [Thread-15   ] [INFO ] [django.server       ]  "GET /notifications/get HTTP/1.1" 304 0
2023-11-12 19:12:19,872 [Thread-15   ] [INFO ] [django.server       ]  "GET /notifications/get HTTP/1.1" 304 0
2023-11-17 09:41:28,973 [MainThread  ] [INFO ] [django.utils.autorel]  Watching for file changes with StatReloader
2023-11-17 09:41:28,973 [MainThread  ] [INFO ] [django.utils.autorel]  Watching for file changes with StatReloader
2023-11-17 09:41:30,994 [MainThread  ] [INFO ] [rq.worker           ]  Worker rq:worker:3d72091b0f2a43a3afd31f030db99a47 started with PID 1122, version 1.14.1
2023-11-17 09:41:30,996 [MainThread  ] [INFO ] [rq.worker           ]  Subscribing to channel rq:pubsub:3d72091b0f2a43a3afd31f030db99a47
2023-11-17 09:41:30,997 [MainThread  ] [INFO ] [rq.worker           ]  *** Listening on default...
2023-11-17 09:41:30,999 [MainThread  ] [INFO ] [rq.worker           ]  Cleaning registries for queue: default
2023-11-17 09:41:31,055 [MainThread  ] [INFO ] [rq.worker           ]  Worker rq:worker:60bd00d12227445c9b50bd7ad70da798 started with PID 1123, version 1.14.1
2023-11-17 09:41:31,056 [MainThread  ] [INFO ] [rq.worker           ]  Subscribing to channel rq:pubsub:60bd00d12227445c9b50bd7ad70da798
2023-11-17 09:41:31,058 [MainThread  ] [INFO ] [rq.worker           ]  *** Listening on dispatch-notifications...
2023-11-17 09:41:31,068 [MainThread  ] [INFO ] [rq.worker           ]  Cleaning registries for queue: dispatch-notifications
2023-11-17 09:45:28,119 [MainThread  ] [INFO ] [rq.worker           ]  Worker 3d72091b0f2a43a3afd31f030db99a47 [PID 1122]: warm shut down requested
2023-11-17 09:45:28,128 [MainThread  ] [INFO ] [rq.worker           ]  Unsubscribing from channel rq:pubsub:3d72091b0f2a43a3afd31f030db99a47
2023-11-17 09:45:28,120 [MainThread  ] [INFO ] [rq.worker           ]  Worker 60bd00d12227445c9b50bd7ad70da798 [PID 1123]: warm shut down requested
2023-11-17 09:45:28,156 [MainThread  ] [INFO ] [rq.worker           ]  Unsubscribing from channel rq:pubsub:60bd00d12227445c9b50bd7ad70da798

Powyższe widomości typu rq.worker były związane ze startem maszyny wirtualnej poleceniem vagrant up. Zgodnie z założeniami, trafiały również do pliku rqworker.log:

2023-11-17 09:41:30,994 [MainThread  ] [INFO ] [rq.worker           ]  Worker rq:worker:3d72091b0f2a43a3afd31f030db99a47 started with PID 1122, version 1.14.1
2023-11-17 09:41:30,996 [MainThread  ] [INFO ] [rq.worker           ]  Subscribing to channel rq:pubsub:3d72091b0f2a43a3afd31f030db99a47
2023-11-17 09:41:30,997 [MainThread  ] [INFO ] [rq.worker           ]  *** Listening on default...
2023-11-17 09:41:30,999 [MainThread  ] [INFO ] [rq.worker           ]  Cleaning registries for queue: default
2023-11-17 09:41:31,055 [MainThread  ] [INFO ] [rq.worker           ]  Worker rq:worker:60bd00d12227445c9b50bd7ad70da798 started with PID 1123, version 1.14.1
2023-11-17 09:41:31,056 [MainThread  ] [INFO ] [rq.worker           ]  Subscribing to channel rq:pubsub:60bd00d12227445c9b50bd7ad70da798
2023-11-17 09:41:31,058 [MainThread  ] [INFO ] [rq.worker           ]  *** Listening on dispatch-notifications...
2023-11-17 09:41:31,068 [MainThread  ] [INFO ] [rq.worker           ]  Cleaning registries for queue: dispatch-notifications
2023-11-17 09:45:28,119 [MainThread  ] [INFO ] [rq.worker           ]  Worker 3d72091b0f2a43a3afd31f030db99a47 [PID 1122]: warm shut down requested
2023-11-17 09:45:28,120 [MainThread  ] [INFO ] [rq.worker           ]  Worker 60bd00d12227445c9b50bd7ad70da798 [PID 1123]: warm shut down requested
2023-11-17 09:45:28,128 [MainThread  ] [INFO ] [rq.worker           ]  Unsubscribing from channel rq:pubsub:3d72091b0f2a43a3afd31f030db99a47
2023-11-17 09:45:28,156 [MainThread  ] [INFO ] [rq.worker           ]  Unsubscribing from channel rq:pubsub:60bd00d12227445c9b50bd7ad70da798

Po Po dodaniu własności propagacji, przykładowo takie logi trafiły do pliku djangoproject.log przy ponownym starcie maszyny:

2023-11-18 11:37:16,587 [MainThread  ] [INFO ] [django.utils.autorel]  Watching for file changes with StatReloader
2023-11-18 11:37:23,084 [Thread-1    ] [INFO ] [django.server       ]  "GET /notifications/get HTTP/1.1" 200 2
2023-11-18 11:37:23,127 [Thread-2    ] [INFO ] [django.server       ]  "GET /static/common/images/favicon.ico HTTP/1.1" 200 1150
2023-11-18 11:37:27,776 [Thread-3    ] [INFO ] [django.server       ]  "GET /offer/ HTTP/1.1" 200 164335
2023-11-18 11:37:28,076 [Thread-3    ] [INFO ] [django.server       ]  "GET /static/common-main_78f37ad1351086911960.css HTTP/1.1" 304 0

Natomiast do pliku rqworker.log trafiły następujące logi:

2023-11-18 11:37:18,371 [MainThread  ] [INFO ] [rq.worker           ]  Worker rq:worker:4ec63c4a2b2848f8b200ae33c5d52fd7 started with PID 1124, version 1.14.1
2023-11-18 11:37:18,384 [MainThread  ] [INFO ] [rq.worker           ]  Subscribing to channel rq:pubsub:4ec63c4a2b2848f8b200ae33c5d52fd7
2023-11-18 11:37:18,387 [MainThread  ] [INFO ] [rq.worker           ]  *** Listening on default...
2023-11-18 11:37:18,392 [MainThread  ] [INFO ] [rq.worker           ]  Cleaning registries for queue: default
2023-11-18 11:37:18,415 [MainThread  ] [INFO ] [rq.worker           ]  Worker rq:worker:41183f19ad89432bbe0f1d099dd98e77 started with PID 1126, version 1.14.1
2023-11-18 11:37:18,416 [MainThread  ] [INFO ] [rq.worker           ]  Subscribing to channel rq:pubsub:41183f19ad89432bbe0f1d099dd98e77
2023-11-18 11:37:18,420 [MainThread  ] [INFO ] [rq.worker           ]  *** Listening on dispatch-notifications...
2023-11-18 11:37:18,423 [MainThread  ] [INFO ] [rq.worker           ]  Cleaning registries for queue: dispatch-notifications
2023-11-18 12:04:18,644 [MainThread  ] [INFO ] [rq.worker           ]  Cleaning registries for queue: dispatch-notifications
2023-11-18 12:04:18,644 [MainThread  ] [INFO ] [rq.worker           ]  Cleaning registries for queue: default
2023-11-18 12:31:18,995 [MainThread  ] [INFO ] [rq.worker           ]  Cleaning registries for queue: default
2023-11-18 12:31:18,995 [MainThread  ] [INFO ] [rq.worker           ]  Cleaning registries for queue: dispatch-notifications