Fix broken ocrd_network processing worker logs

[MehmedGIT]

The processing worker logger acted weirdly for some time. Pay attention to the log levels produced by self.log.__dict__

2024-10-14 14:57:54,874.874 WARNING ocrd_network.processing_worker - ---------- __init__() CONFIGURED LOGGER: {'filters': [], 'name': 'ocrd_network.processing_worker', 'level': 0, 'parent': <Logger ocrd_network (WARNING)>, 'propagate': True, 'handlers': [<FileHandler /tmp/ocrd_network_logs/processing_workers/worker.843428.ocrd-cis-ocropy-binarize.log (NOTSET)>], 'disabled': False, '_cache': {10: False, 20: False, 40: True}, 'manager': <logging.Manager object at 0x7fa652ba9b50>}
2024-10-14 14:57:54,879.879 WARNING ocrd_network.processing_worker - ---------- start_consuming() CONFIGURED LOGGER: {'filters': [], 'name': 'ocrd_network.processing_worker', 'level': 0, 'parent': <Logger ocrd_network (WARNING)>, 'propagate': True, 'handlers': [<FileHandler /tmp/ocrd_network_logs/processing_workers/worker.843428.ocrd-cis-ocropy-binarize.log (NOTSET)>], 'disabled': False, '_cache': {10: False, 20: False, 40: True, 30: True}, 'manager': <logging.Manager object at 0x7fa652ba9b50>}
2024-10-14 14:58:12,140.140 WARNING ocrd_network.processing_worker - ---------- on_consumed_message() CONFIGURED LOGGER: {'filters': [], 'name': 'ocrd_network.processing_worker', 'level': 0, 'parent': <Logger ocrd_network (WARNING)>, 'propagate': True, 'handlers': [<FileHandler /tmp/ocrd_network_logs/processing_workers/worker.843428.ocrd-cis-ocropy-binarize.log (NOTSET)>], 'disabled': False, '_cache': {10: False, 20: False, 40: True, 30: True}, 'manager': <logging.Manager object at 0x7fa652ba9b50>}
2024-10-14 14:58:12,141.141 WARNING ocrd_network.processing_worker - ---------- process_message() CONFIGURED LOGGER: {'filters': [], 'name': 'ocrd_network.processing_worker', 'level': 0, 'parent': <Logger ocrd_network (WARNING)>, 'propagate': True, 'handlers': [<FileHandler /tmp/ocrd_network_logs/processing_workers/worker.843428.ocrd-cis-ocropy-binarize.log (NOTSET)>], 'disabled': False, '_cache': {10: False, 20: False, 40: True, 30: True}, 'manager': <logging.Manager object at 0x7fa652ba9b50>}
2024-10-14 14:58:15,279.279 WARNING ocrd_network.processing_worker - ---------- publish_result_to_all() CONFIGURED LOGGER: {'filters': [], 'name': 'ocrd_network.processing_worker', 'level': 0, 'parent': <Logger ocrd_network (INFO)>, 'propagate': True, 'handlers': [<FileHandler /tmp/ocrd_network_logs/processing_workers/worker.843428.ocrd-cis-ocropy-binarize.log (NOTSET)>], 'disabled': False, '_cache': {20: True, 40: True}, 'manager': <logging.Manager object at 0x7fa652ba9b50>}
2024-10-14 14:58:15,279.279 INFO ocrd_network.processing_worker - Result message: {'job_id': 'b3efe133-7c7d-4316-abc1-d99c35c5f62b', 'state': 'SUCCESS', 'workspace_id': '', 'path_to_mets': '/home/mm/repos/ocrd_network_tests/ws29/data/mets.xml'}
2024-10-14 14:58:15,280.280 INFO ocrd_network.processing_worker - Publishing result to internal callback url (Processing Server): None
2024-10-14 14:58:15,280.280 INFO ocrd_network.processing_worker - Posting result message to callback_url "http://localhost:8080/result_callback"
2024-10-14 14:58:15,317.317 INFO ocrd_network.processing_worker - Response from callback_url "<Response [200]>"
2024-10-14 14:58:15,318.318 INFO ocrd_network.processing_worker - Successfully processed RabbitMQ message
2024-10-14 14:58:15,320.320 WARNING ocrd_network.processing_worker - ---------- on_consumed_message() CONFIGURED LOGGER: {'filters': [], 'name': 'ocrd_network.processing_worker', 'level': 0, 'parent': <Logger ocrd_network (INFO)>, 'propagate': True, 'handlers': [<FileHandler /tmp/ocrd_network_logs/processing_workers/worker.843428.ocrd-cis-ocropy-binarize.log (NOTSET)>], 'disabled': False, '_cache': {20: True, 40: True, 30: True, 10: False}, 'manager': <logging.Manager object at 0x7fa652ba9b50>}

To reproduce it is enough to print the logger object at the beginning of each method:

self.log.warning(f"{self.log.__dict__}")

Seems when jiggling with the logging in the past, the initLogging() call was removed from the processing worker. The logger level is still set to INFO at some point, but an implicit call to initLogging() sets the logger level earlier. I think we had to remove that call in the past because initLogging() was called in other places which led to conflicts.

[bertsky]

Wow – thanks for digging!

Still strange why the correct log level would be set somewhere between process_message and publish_result_to_all...