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: listname(a)example.com<mailto:listname@example.com>
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/listname(a)example.com<mailto:/3.1/lists/listname@example.com>
* [2026-08-03 12:15:29 +0000] [52] [DEBUG] GET /3.1/lists/listname(a)example.com<mailto:/3.1/lists/listname@example.com>
* [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/listname(a)example.com/config<mailto:/3.1/lists/listname@example.com/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/listname(a)example.com/config<mailto:/3.1/lists/listname@example.com/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/listname(a)example.com/config<mailto:/3.1/lists/listname@example.com/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
