Hello, I have been chatting with Copilot AI for some days to get help investigating some logging-related issues in a Mailman 3.3.4 Docker installation and, so I would appreciate any guidance.
We are working on a long needed upgrade, but for now I need the logs in Elasticsearch, and they are aweful. Environment * GNU Mailman 3.3.4 (Tom Sawyer) * Python 3.8.10 * Docker-based installation * Test environment with a single mailing list: [email protected]<mailto:[email protected]> Logging configuration I've configured dedicated log files for most logging channels. For example, [logging.http] is configured with format: %(asctime)s (%(process)d) %(message)s, datefmt: %Y-%m-%d %H:%M:%S.%3N, propagate: no, level: debug, and path: http.log. All [logging.*] sections in the generated /etc/mailman-extra.cfg use the same datefmt. format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: info path: mailman.log [logging.archiver] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: archiver.log [logging.bounce] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: bounce.log [logging.config] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: config.log [logging.database] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: database.log [logging.debug] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: debug.log [logging.error] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: error.log [logging.fromusenet] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: fromusenet.log [logging.http] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: http.log [logging.locks] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: locks.log [logging.mischief] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: mischief.log [logging.plugins] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: plugins.log [logging.runner] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: info path: runner.log [logging.smtp] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: info path: smtp.log [logging.smtp-failure] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: smtp-failure.log [logging.subscribe] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: subscribe.log [logging.vette] format: %(asctime)s (%(process)d) %(message)s datefmt: %Y-%m-%d %H:%M:%S.%3N propagate: no level: debug path: vette.log Issue 1: Mixed log formats Despite configuring all logging sections with datefmt: %Y-%m-%d %H:%M:%S.%3N, I still see multiple timestamp formats in mailman.log, for example: * [30/Jul/2026:12:00:03 +0000] "GET /3.1/lists?count=10&page=1 HTTP/1.1" 200 90 "-" "GNU Mailman REST client v3.3.3" * [2026-07-30 12:32:15 +0000] [36] [INFO] Shutting down: Master * Jul 30 12:32:14 2026 (1) Master watcher caught SIGTERM. Exiting This suggests that multiple logging systems may be writing to the same log file. Issue 2: Runner debug noise With logging level set to debug, mailman.log contains a large number of entries such as: * Jul 31 07:58:12 2026 (33) [PipelineRunner] starting oneloop * Jul 31 07:58:12 2026 (33) [PipelineRunner] ending oneloop: 0 * Jul 31 07:58:12 2026 (26) [ArchiveRunner] starting oneloop * Jul 31 07:58:12 2026 (26) [ArchiveRunner] ending oneloop: 0 * Jul 31 07:58:12 2026 (29) [IncomingRunner] starting oneloop * Jul 31 07:58:12 2026 (29) [IncomingRunner] ending oneloop: 0 * Jul 31 07:58:13 2026 (28) [CommandRunner] starting oneloop * Jul 31 07:58:13 2026 (36) [VirginRunner] starting oneloop * Jul 31 07:58:13 2026 (36) [VirginRunner] ending oneloop: 0 * Jul 31 07:58:13 2026 (28) [CommandRunner] ending oneloop: 0 * Jul 31 07:58:13 2026 (37) [DigestRunner] starting oneloop * Jul 31 07:58:13 2026 (37) [DigestRunner] ending oneloop: 0 * Jul 31 07:58:13 2026 (31) [NNTPRunner] starting oneloop * Jul 31 07:58:13 2026 (32) [OutgoingRunner] starting oneloop * Jul 31 07:58:13 2026 (31) [NNTPRunner] ending oneloop: 0 * Jul 31 07:58:13 2026 (32) [OutgoingRunner] ending oneloop: 0 Is there a recommended way to suppress these internal runner loop messages while retaining useful operational logging? Issue 3: HTTP request logging I intentionally keep [logging.http] at level: debug because I want to see which REST endpoints are called. Examples: * [2026-08-03 12:10:28 +0000] [51] [DEBUG] GET /3.1/lists/[email protected]<mailto:/3.1/lists/[email protected]> * [2026-08-03 12:15:29 +0000] [52] [DEBUG] GET /3.1/lists/[email protected]<mailto:/3.1/lists/[email protected]> * [2026-08-03 13:00:03 +0000] [53] [DEBUG] GET /3.1/lists My goal is to keep these request entries. Issue 4: Falcon tracebacks in http.log The same http.log also contains Falcon tracebacks. One example is: 2026-08-03 12:10:29 [FALCON] [ERROR] GET /3.1/lists/[email protected]/config<mailto:/3.1/lists/[email protected]/config> => Traceback (most recent call last): File "/usr/lib/python3.8/site-packages/sqlalchemy/engine/result.py", line 779, in _getter getter = self._metadata._getter AttributeError: 'NoneType' object has no attribute '_getter' The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/usr/lib/python3.8/site-packages/falcon/app.py", line 361, in call responder(req, resp, **params) File "/usr/lib/python3.8/site-packages/mailman/rest/listconf.py", line 282, in on_get value = getter.get(self._mlist, attribute) File "/usr/lib/python3.8/site-packages/mailman/rest/listconf.py", line 52, in get return sorted(aliases.aliases) File "/usr/lib/python3.8/site-packages/mailman/model/mailinglist.py", line 565, in aliases for alias in aliases File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/loading.py", line 100, in instances cursor.close() File "/usr/lib/python3.8/site-packages/sqlalchemy/util/langhelpers.py", line 68, in exit compat.raise_( File "/usr/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise_ raise exception File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/loading.py", line 58, in instances *[ File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/loading.py", line 59, in query_entity.row_processor(query, context, cursor) File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 4422, in row_processor _instance = loading._instance_processor( File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/loading.py", line 421, in _instance_processor getter = result._getter(col, False) File "/usr/lib/python3.8/site-packages/sqlalchemy/engine/result.py", line 781, in _getter return self._non_result(None, err) File "/usr/lib/python3.8/site-packages/sqlalchemy/engine/result.py", line 1236, in non_result util.raise( File "/usr/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise_ raise exception sqlalchemy.exc.ResourceClosedError: This result object does not return rows. It has been closed automatically. Is it possible to: 1. Continue logging HTTP GET requests to http.log 2. Send Falcon tracebacks and REST API errors to a separate log file At the moment, both request logging and tracebacks appear in the same file. Issue 5: Worker timeout After the traceback above, I consistently see: * [2026-08-03 12:21:29 +0000] [34] [CRITICAL] WORKER TIMEOUT (pid:52) * [2026-08-03 12:21:30 +0000] [53] [INFO] Booting worker with pid: 53 This appears to indicate that the worker handling GET /3.1/lists/[email protected]/config<mailto:/3.1/lists/[email protected]/config> times out and is restarted. Additional observations error.log contains Mailman Core exceptions such as: (52) deque: subscribe_from_restored Traceback (most recent call last): File "/usr/lib/python3.8/site-packages/mailman/app/workflow.py", line 69, in next return step() File "/usr/lib/python3.8/site-packages/mailman/app/subscriptions.py", line 341, in _step_get_moderator_approval raise StopIteration StopIteration However, the Falcon/REST traceback shown above does not appear in error.log. This suggests that: * error.log receives Mailman Core exceptions. * http.log receives REST API/Falcon exceptions. * The two do not appear to be linked. Questions 1. Is the mixed timestamp formatting expected in Mailman 3.3.4 Docker deployments? 2. Which component produces the starting oneloop / ending oneloop runner messages? 3. Can HTTP request logging and Falcon tracebacks be directed to separate log files? 4. Is ResourceClosedError when accessing GET /3.1/lists/[email protected]/config<mailto:/3.1/lists/[email protected]/config> a known Mailman 3.3.4 issue? 5. Is there a recommended logging configuration that preserves REST API access logging while reducing runner/debug noise? Thanks in advance. Best regards, Henrik _______________________________________________ Mailman-users mailing list -- [email protected] To unsubscribe send an email to [email protected] https://lists.mailman3.org/mailman3/lists/mailman-users.mailman3.org/ Archived at: https://lists.mailman3.org/archives/list/[email protected]/message/VMPCOVAODFXSNRKH5ZUVM3I53ZX7LOWG/ This message sent to [email protected]
