empty log lines in container logs

[elliotdobson]

Hi there,

I have just configured a new ejabberd server in docker/kubernetes and I have noticed that we are getting an empty log line for every log line that the container is outputting.

2024-09-06T03:23:04.926927427Z 
2024-09-06T03:23:04.927009844Z 03:23:04.909 [info] Loading configuration from /opt/ejabberd/conf/ejabberd.yml
2024-09-06T03:23:04.960031844Z 
2024-09-06T03:23:04.960079344Z 03:23:04.959 [notice] Changing loglevel from 'debug' to 'info'
2024-09-06T03:23:05.461899261Z 
2024-09-06T03:23:05.461930219Z 03:23:05.460 [info] Configuration loaded successfully
2024-09-06T03:23:05.665459511Z 
2024-09-06T03:23:05.665483802Z 03:23:05.665 [info] Got no NOTIFY_SOCKET, notifications disabled
2024-09-06T03:23:05.819625427Z 
2024-09-06T03:23:05.819653886Z 03:23:05.818 [info] Loading modules for xmpp.example.com
2024-09-06T03:23:05.823538511Z 
2024-09-06T03:23:05.823570261Z 03:23:05.822 [warning] Mnesia backend for mod_mam is not recommended: it's limited to 2GB and often gets corrupted when reaching this limit. SQL backend is recommended. Namely, for small servers SQLite is a preferred choice because it's very easy to configure.
2024-09-06T03:23:06.031620636Z 
2024-09-06T03:23:06.031666928Z 03:23:06.031 [info] Building MQTT cache for xmpp.example.com, this may take a while
2024-09-06T03:23:06.039169136Z 
2024-09-06T03:23:06.039193386Z 03:23:06.038 [warning] The option captcha_cmd is not configured, but some module wants to use the CAPTCHA feature.
2024-09-06T03:23:06.082963886Z 
2024-09-06T03:23:06.082994428Z 03:23:06.082 [info] Waiting for Mnesia synchronization to complete
2024-09-06T03:23:06.179845094Z 
2024-09-06T03:23:06.179865803Z 03:23:06.179 [warning] No certificate found matching upload.xmpp.example.com
2024-09-06T03:23:06.179867761Z 
2024-09-06T03:23:06.179868803Z 03:23:06.179 [warning] No certificate found matching pubsub.xmpp.example.com
2024-09-06T03:23:06.180233428Z 
2024-09-06T03:23:06.180247678Z 03:23:06.179 [warning] No certificate found matching conference.xmpp.example.com
2024-09-06T03:23:06.180249303Z 
2024-09-06T03:23:06.180250511Z 03:23:06.180 [warning] No certificate found matching proxy.xmpp.example.com
2024-09-06T03:23:06.220202386Z 
2024-09-06T03:23:06.220237969Z 03:23:06.181 [info] ejabberd 24.7.0 is started in the node :ejabberd@localhost in 1.38s
2024-09-06T03:23:06.225890178Z 
2024-09-06T03:23:06.225905053Z 03:23:06.222 [info] Start accepting TLS connections at [::]:5443 for :ejabberd_http
2024-09-06T03:23:06.226127594Z 
2024-09-06T03:23:06.226133053Z 03:23:06.222 [info] Start accepting TCP connections at [::]:5222 for :ejabberd_c2s
2024-09-06T03:23:06.226134511Z 
2024-09-06T03:23:06.226135678Z 03:23:06.222 [info] Start accepting TCP connections at 172.20.0.6:7777 for :mod_proxy65_stream
2024-09-06T03:23:06.226176678Z 
2024-09-06T03:23:06.226178428Z 03:23:06.224 [info] Start accepting TCP connections at [::]:5280 for :ejabberd_http
2024-09-06T03:23:06.226188428Z 
2024-09-06T03:23:06.226189511Z 03:23:06.224 [info] Start accepting TLS connections at [::]:5223 for :ejabberd_c2s

We are using the latest version: ghcr.io/processone/ejabberd:24.07

Has anyone come across this before?

Thanks

[badlop]

It's a known weirdness. In some cases the log line only contains time, not date, and the log line contains an additional return carriage.

I've tried again: logging looks correct when:

• compiled from source code with rebar3 or mix
• using binary installers
• generating ejabberd container image manually (uses default method)
• generating ejabberd container image in github actions (uses package method), see [1]

Logging looks weird when:

• using ejabberd container for 24.07 from ghcr.io, see [2]
• using ecs container for 24.07 from ghcr.io

[1]

$ podman run --name ejabberd -it -p 5222:5222 ghcr.io/badlop/ejabberd:dependabot live
2024-09-06 16:02:41.793 [info] Loading configuration from /opt/ejabberd/conf/ejabberd.yml
2024-09-06 16:02:42.200 [info] Configuration loaded successfully
2024-09-06 16:02:42.341 [info] Got no NOTIFY_SOCKET, notifications disabled
2024-09-06 16:02:42.350 [info] Building language translation cache

[2]

$ podman run --name ejabberd -it -p 5222:5222 ghcr.io/processone/ejabberd live
10:02:14.087 [info] Loading configuration from /opt/ejabberd/conf/ejabberd.yml

10:02:14.127 [notice] Changing loglevel from 'debug' to 'info'

10:02:14.646 [info] Configuration loaded successfully

10:02:14.857 [info] Got no NOTIFY_SOCKET, notifications disabled

[badlop]

I suspect the problem was introduced in 24.07, probably in 7a8c033 and/or aa02c4d.

The container images built from 24.02, and from master branch no longer have this problem, probably it got solved in
b07e28b and/or e99fe98.

We will know for sure if the problem is definitely solved when the next version is released.

[elliotdobson]

Great thanks for that info. Is there a timeline on the next release?

[badlop]

The next release will probably be ejabberd 24.10, in that case it would be released sometime during this month of October

[elliotdobson]

Tested ejabberd 24.10 and I can confirm that the empty log lines are fixed now. Thanks @badlop!