2.0.12: log_timestamp_format crashing broker

[jipp]

running mosquitto inside a docker container on raspberry os:

uname -a
Linux lemonpi 5.10.60-v8+ #1449 SMP PREEMPT Wed Aug 25 15:01:33 BST 2021 aarch64 GNU/Linux

docker version
Client: Docker Engine - Community
 Version:           20.10.8
 API version:       1.41
 Go version:        go1.16.6
 Git commit:        3967b7d
 Built:             Fri Jul 30 19:55:38 2021
 OS/Arch:           linux/arm
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.8
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.16.6
  Git commit:       75249d8
  Built:            Fri Jul 30 19:53:31 2021
  OS/Arch:          linux/arm
  Experimental:     true
 containerd:
  Version:          1.4.9
  GitCommit:        e25210fe30a0a703442421b0f60afac609f950a3
 runc:
  Version:          1.0.1
  GitCommit:        v1.0.1-0-g4144b63
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

running the following config with 2.0.11 and before is working fine:

mosquitto.conf

persistence true
persistence_location /mosquitto/data/

log_timestamp true
#log_timestamp_format %m/%d/%y %H:%M:%S
log_timestamp_format %Y-%m-%dT%H:%M:%S
log_dest stderr
log_dest file /mosquitto/log/mosquitto.log

log 2.0.11:

1631175402: Loading config file /mosquitto/config/conf.d/debug.conf
1631175402: Loading config file /mosquitto/config/conf.d/security.conf
1631175402: Loading config file /mosquitto/config/conf.d/tls.conf
2021-09-09T08:16:42: mosquitto version 2.0.11 starting
2021-09-09T08:16:42: Config loaded from /mosquitto/config/mosquitto.conf.
2021-09-09T08:16:42: Opening ipv4 listen socket on port 1883.
2021-09-09T08:16:42: Opening ipv6 listen socket on port 1883.
2021-09-09T08:16:42: Opening ipv4 listen socket on port 8883.
2021-09-09T08:16:42: Opening ipv6 listen socket on port 8883.
2021-09-09T08:16:42: mosquitto version 2.0.11 running
2021-09-09T08:46:44: Saving in-memory database to /mosquitto/data//mosquitto.db.

switching to 2.0.12 crashes the broker:

0: Loading config file /mosquitto/config/conf.d/debug.conf
0: Loading config file /mosquitto/config/conf.d/security.conf
0: Loading config file /mosquitto/config/conf.d/tls.conf
Error obtaining system time.

removing the log_timestamp_format %Y-%m-%dT%H:%M:%S from the config it starts like expected:

0: Loading config file /mosquitto/config/conf.d/debug.conf
0: Loading config file /mosquitto/config/conf.d/security.conf
0: Loading config file /mosquitto/config/conf.d/tls.conf
0: mosquitto version 2.0.12 starting
0: Config loaded from /mosquitto/config/mosquitto.conf.
0: Opening ipv4 listen socket on port 1883.
0: Opening ipv6 listen socket on port 1883.
0: Opening ipv4 listen socket on port 8883.
0: Opening ipv6 listen socket on port 8883.
0: mosquitto version 2.0.12 running

[ralight]

This is interesting, there are no changes from 2.0.11 to 2.0.12 around the logging format, or even the logging file at all, so it's a bit of a surprise. Do you see the same issue on different systems, or outside of Docker?

[jipp]

Based on your comment I did some more investigations.

the difference between 2.0.12 and 2.0.11 is not in t he source code, but in the base image.

pi@lemonpi:~/docker-compose $ docker run -it --rm eclipse-mosquitto:2.0.11 cat /etc/alpine-release
3.12.8
pi@lemonpi:~/docker-compose $ docker run -it --rm eclipse-mosquitto:2.0.12 cat /etc/alpine-release
3.14.2

This seems not to be important on most docker platforms, but when using a Raspberry with Raspberry Pi OS it is.

From 3.13 onwards the following behavior was introduced: alpinelinux/docker-alpine#135

by following the described workarounds I got 2.0.12 running on my system.

thx a lot - the hint that there have been no changes was good enough to dig deeper :-)

[peter-vanpoucke]

It looks like it's related to alpinelinux/docker-alpine#135 indeed.

Fix at #2323 (comment)