opensmtpd: Does not respect the system time zone in mail header and logfile

[ffobzb]

Is this a new report?

Yes

System Info

Void 4.9.261_1 x86_64 glibc

Package(s) Affected

opensmtpd-6.8.0p2_4

Does a report exist for this bug with the project's home (upstream) and/or another distro?

No response

Expected behaviour

In the headers of the tranferred mail and in the logfiles the MTA should use times with the time zone which was set up for this system.

Actual behaviour

OpenSMTPD seems to write times in UTC instead of my system time zone (Europe/Berlin, actually UTC+2).
Example header from a local delivered mail:

From abc  Wed Sep 28 21:09:55 2022  
Return-Path: <webmaster@yourdomain.com>  
Delivered-To: abc@localhost  
Received: from localhost (xyz.localdomain [local])  
        by xyz.localdomain (OpenSMTPD) with ESMTPA id 020e7525  
        for <abc@localhost>;  
        Wed, 28 Sep 2022 19:09:55 +0000 (UTC)  
Date: Wed, 28 Sep 2022 21:09:55 +0200 (CEST)  
To: abc@localhost  
From: webmaster@yourdomain.com  
Subject: Test Email  
Message-ID: <b4b222b031806af8@xyz.localdomain>  

In the "Date" header the local time in the correct time zone is used. In the "Received" header which is added by OpenSMTPD the time is stated in UTC, regardless of the time zone of the system.

The same problem exists for the log file (/var/log/socklog/mail/current):

2022-09-28T19:09:10.78118 mail.info: Sep 28 21:09:10 smtpd[2699]: info: OpenSMTPD 6.8.0p2 starting
2022-09-28T19:09:55.62957 mail.info: Sep 28 21:09:55 smtpd[2703]: b4b222afa5939ddc smtp connected address=local host=xyz.localdomain
2022-09-28T19:09:55.63338 mail.info: Sep 28 19:09:55 smtpd[2703]: b4b222afa5939ddc smtp message msgid=020e7525 size=389 nrcpt=1 proto=ESMTP
2022-09-28T19:09:55.63342 mail.info: Sep 28 19:09:55 smtpd[2703]: b4b222afa5939ddc smtp envelope evpid=020e752572255a45 from=<webmaster@yourdomain.com> to=<abc@localhost>
2022-09-28T19:09:55.63347 mail.info: Sep 28 19:09:55 smtpd[2703]: b4b222afa5939ddc smtp disconnected reason=quit
2022-09-28T19:09:57.64998 mail.info: Sep 28 19:09:57 smtpd[2703]: b4b222b1cbdebff4 mda delivery evpid=020e752572255a45 from=<webmaster@yourdomain.com> to=<abc@localhost> rcpt=<abc@localhost> user=abc delay=2s result=Ok stat=Delivered
2022-09-28T19:11:20.45865 mail.info: Sep 28 21:11:20 smtpd[2699]: Exiting

When the OpenSMTPD process starts it logs with the local time (21:09:10). When processing mails it changes over to UTC (19:09:55). And when it exits it uses local time again (21:11:20). I don't think that this behaviour is intended.

Maybe the _smtpd or the _smtpq user to which OpenSMTPD drops privileges is not able to read the setted up time zone? Therefore this problem is maybe Void specific, since I haven't found any bug reports from other distributions or from OpenBSD regarding this.

Steps to reproduce

1. Start opensmtpd
2. Send a local mail to yourself on the system
3. Check the mail headers for the time zone in the "Received" header
4. Check /var/log/socklog/mail/current for the logged times

[sdgathman]

1. Does the standard say Received headers should use local timezone?
2. I actually would prefer Received headers in UTC. I have to mentally convert them all to UTC to get a timeline of the message.
3. Maybe there is an opensmtp config for header timestamps that doesn't default to system time zone.
4. What timezone does Date header use when you send (as oppose to receive) a message?

I mostly use sendmail, but I have a few opensmtp installs and will look for 3.

[sdgathman]

There doesn't seem to be any SHOULD or MUST for the Received header being any particular timezone. The only MUSTard is a gateway MUST NOT alter Received headers from other systems. https://www.rfc-editor.org/rfc/rfc2821#section-3.8.2

[sdgathman]

Date fields, including Received header, SHOULD use local time expressed as offset from UTC (not TZ abbreviation). https://www.rfc-editor.org/rfc/rfc2822#section-3.3

If localtime is UTC, they SHOULD use +0000. If defaulting to UTC because localtime is unknown - they SHOULD use -0000.

Your example uses +0000. Also, your log example uses the same TZ from the logging system and from opensmtpd - suggesting that they both use the same config. That sounds to me like you have the system configured to UTC, and have only configured a personal preference somewhere as CEST. The Date header is normally generated by the email client, not opensmtpd.

[sdgathman]

I checked OpenSMTPd installs on Fedora, and it also uses +0000 for Received Header fields that it adds.

I have no objection to using UTC - it fits the purpose of Received for tracing. However, the RFC recommends using -0000 to indicate when that is not actually the local time zone.

[ffobzb]

Thanks a lot for your investigations.

Yes, the Date header isn't from OpenSMTPd, and the Date header is not the problem because it shows local times.

The logging system (socklog) shows the time stamps in UTC, yes. But the time stamps from the processes in the logs use local time. In my example logfile above you can see that when OpenSMTPd starts (PID 2699) it logs correctly with local time, but when processing the mail within a forked process (PID 2703) it jumps to UTC. When stopping the process (PID 2699) it then jumps back to local time.

I don't think that this behaviour is intended or that OpenSMTPd uses generally UTC times in headers. Two reasons for that:

1. In the source code the time stamps for the Received header (and probably also for the logging) are generated in the function time_to_text in the source file to.c:

const char *
time_to_text(time_t when)
{
	struct tm *lt;
	static char buf[40];
	char *day[] = {"Sun", "Mon", "Tue", "Wed", "Thu", "Fri", "Sat"};
	char *month[] = {"Jan","Feb","Mar","Apr","May","Jun",
			 "Jul","Aug","Sep","Oct","Nov","Dec"};
	const char *tz;
	long offset;

	lt = localtime(&when);
	if (lt == NULL || when == 0)
		fatalx("time_to_text: localtime");

#if HAVE_STRUCT_TM_TM_GMTOFF
	offset = lt->tm_gmtoff;
	tz = lt->tm_zone;
#elif defined HAVE_DECL_ALTZONE && defined HAVE_DECL_TIMEZONE
	offset = lt->tm_isdst > 0 ? altzone : timezone;
	tz = lt->tm_isdst > 0 ? tzname[1] : tzname[0];
#endif

	/* We do not use strftime because it is subject to locale substitution*/
	if (!bsnprintf(buf, sizeof(buf),
	    "%s, %d %s %d %02d:%02d:%02d %c%02d%02d (%s)",
	    day[lt->tm_wday], lt->tm_mday, month[lt->tm_mon],
	    lt->tm_year + 1900,
	    lt->tm_hour, lt->tm_min, lt->tm_sec,
	    offset >= 0 ? '+' : '-',
	    abs((int)offset / 3600),
	    abs((int)offset % 3600) / 60,
	    tz))
		fatalx("time_to_text: bsnprintf");

	return buf;
}

So the variable lt is filled with the libc function localtime, then the time zone is extracted etc. The intention is clear: The time stamps should be in the systems time zone. If time stamps should be always just UTC this function would be much simpler.

2. I tested the same on an OpenBSD system with OpenSMTPd. There the Received header and the logging uses time stamps in local time, as expected. And the source code in the concerning areas of to.c is the same between the OpenBSD version and the Linux/other version.

Regarding my system config for the time zone: It is set to CET/CEST, because /etc/localtime is a symlink to /usr/share/zoneinfo/Europe/Berlin, and this means the system is configured to use CET and not UTC.

Is your Fedora installation configured to use UTC as time zone? If no, then that would indicate that the problem is not Void specific, but Linux specific...

A configuration option for the time stamps does not exist - at least not a documented one.

My suspicion is still that the problem has to do with the fork resp. privilege drop to the _smtpd or _smtpq user. Somehow the configured system time zone disappears then.

[vmc-coding]

I've this problem on Gentoo Linux also, do you have filed an upstream bug?

[ffobzb]

After a short break of several months :-) I picked up this issue again. I think I found the reason for the behaviour and a suitable workaround.

The chroot'ed processes can't access /etc/localtime and thus fall back to UTC. This shall be prevented by the call of tzset(3) before the chroot, and on OpenBSD this works. But in GNU libc the behaviour is - as far as I understood it - different: If the environment variable TZ is not set, then each call of a time-related function looks up the time zone again, and this fails after the chroot because /etc/localtime isn't accessible. This means that the tzset() call before is useless in case of GNU libc.

If TZ is not empty and is set to a timezone string before starting smtpd then all works as expected: Mail headers and log entries have the times in the configured time zone. This also works when TZ is set to the filespec format (see tzset(3)).

So the workaround is as simple as setting TZ before starting smtpd:

# TZ=/etc/localtime smtpd

And the corresponding entry in /etc/sv/opensmtpd/run then should be:
TZ=/etc/localtime exec smtpd -F 2>&1