1303305 – errors from esmtp in /var/log/messages every time my cron job runs

Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.

Bug 1303305 - errors from esmtp in /var/log/messages every time my cron job runs

Summary: errors from esmtp in /var/log/messages every time my cron job runs

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Fedora
Classification:	Fedora
Component:	esmtp
Sub Component:
Version:	23
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	---
Assignee:	Ondřej Lysoněk
QA Contact:	Fedora Extras Quality Assurance
Docs Contact:
URL:
Whiteboard:
Duplicates (5):	1046468 1149164 1256851 1321465 1362685 (view as bug list)
Depends On:	1366173
Blocks:
TreeView+	depends on / blocked

Reported:	2016-01-30 13:44 UTC by Jonathan Wakely
Modified:	2016-10-27 14:29 UTC (History)
CC List:	15 users (show)
Fixed In Version:	esmtp-1.2-3.fc24 esmtp-1.0-15.fc23 esmtp-1.2-4.fc25 esmtp-1.2-4.fc24 esmtp-1.0-16.fc23
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2016-10-09 18:50:05 UTC
Type:	Bug
Embargoed:
Dependent Products:

Attachments	(Terms of Use)

Description Jonathan Wakely 2016-01-30 13:44:22 UTC

I have a cron job that runs every 5 minutes and every time it runs I get the following in /var/log/messages:

Jan 30 13:35:01 knitphad crond: /usr/sbin/sendmail: line 36: /dev/stdin: Permission denied
Jan 30 13:35:01 knitphad crond: could not enqueue mail in dir /home/jwakely/.esmtp_queue/2hF0qXpq
Jan 30 13:35:01 knitphad crond: /usr/sbin/sendmail: line 83: return: can only `return' from a function or sourced script
Jan 30 13:35:01 knitphad audit: CRED_DISP pid=3564 uid=0 auid=1000 ses=6 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="jwakely" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success'
Jan 30 13:35:01 knitphad audit: USER_END pid=3564 uid=0 auid=1000 ses=6 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:session_close grantors=pam_loginuid,pam_keyinit,pam_limits,pam_systemd acct="jwakely" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success'
Jan 30 13:35:06 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/2hF0qXpq/mail: No such file or directory
Jan 30 13:35:11 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/a9Fezrga/mail: No such file or directory
Jan 30 13:35:16 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/c8otHT9w/mail: No such file or directory
Jan 30 13:35:21 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/KFnkgfd2/mail: No such file or directory

The error about 'return' is Bug 1225597 but the rest doesn't seem to be reported. Why is it trying to write to a non-existent directory? If that directory is needed for local mail delivery, why wasn't it created when anaconda created the user?

This is a recent F23 installation, with no customization of the mail config, or anything else in /etc except for /etc/hosts

esmtp-1.0-14.fc23.x86_64
cronie-1.5.0-3.fc23.x86_64

Comment 1 Jonathan Wakely 2016-01-30 13:45:45 UTC

(In reply to Jonathan Wakely from comment #0)
> The error about 'return' is Bug 1225597 but the rest doesn't seem to be
> reported. Why is it trying to write to a non-existent directory? If that
> directory is needed for local mail delivery, why wasn't it created when
> anaconda created the user?

My mistake, the directory does exist, and is owned by my user, so what do the errors mean?

Comment 2 Fedora Admin XMLRPC Client 2016-02-12 18:21:33 UTC

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

Comment 3 Fedora Admin XMLRPC Client 2016-02-14 23:18:46 UTC

This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

Comment 4 Jonathan Wakely 2016-02-24 19:57:25 UTC

I now have gigabytes of logs full of this rubbish, several times a second:

Feb 22 03:40:56 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/oSuLIpz8/mail: No such file or directory
Feb 22 03:40:56 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/EO4LEVrj/mail: No such file or directory
Feb 22 03:40:56 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/eXdCcqId/mail: No such file or directory
Feb 22 03:40:56 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/P57pQAgm/mail: No such file or directory
Feb 22 03:40:56 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/Pfqeg6nZ/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/ATOfPn1i/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/AFJXcGYR/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/amCKyFPw/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/b8nKQHtG/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/FBroeMBj/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/XQWDbF7j/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/tpqTkVpm/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/FHYs8hyD/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/fOGvF03I/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/fXQW0rO3/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/kdYQyglJ/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/gbASbCDm/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/KMAGrSHP/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/17pr6AmV/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/1T1qos5h/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/YEFvBvYr/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/LBo11Bkv/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/uctHD6Bj/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/tzvXhetK/mail: No such file or directory
Feb 22 03:40:57 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/2i67apg1/mail: No such file or directory
Feb 22 03:40:58 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/34uGSKES/mail: No such file or directory
Feb 22 03:40:58 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/PXAZoEsF/mail: No such file or directory
Feb 22 03:40:58 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/LL9SNK99/mail: No such file or directory
Feb 22 03:40:58 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/3RFC7wg1/mail: No such file or directory
Feb 22 03:40:58 knitphad crond: /usr/sbin/sendmail: line 64: /home/jwakely/.esmtp_queue/4gYixwtk/mail: No such file or directory

Comment 5 Jonathan Wakely 2016-02-24 20:31:21 UTC

ps shows over a hundred sendmail processes:

[root@knitphad ~]# ps -ef | fgrep sendmail
jwakely    309     1  0 15:05 ?        00:00:05 /bin/bash /usr/sbin/sendmail -FCronDaemon -i -odi -oem -oi -t -f jwakely
jwakely    601     1  0 16:40 ?        00:00:03 /bin/bash /usr/sbin/sendmail -FCronDaemon -i -odi -oem -oi -t -f jwakely
jwakely    767     1  0 13:50 ?        00:00:06 /bin/bash /usr/sbin/sendmail -FCronDaemon -i -odi -oem -oi -t -f jwakely
jwakely    935     1  0 19:05 ?        00:00:01 /bin/bash /usr/sbin/sendmail -FCronDaemon -i -odi -oem -oi -t -f jwakely
jwakely   1071     1  0 10:55 ?        00:00:09 /bin/bash /usr/sbin/sendmail -FCronDaemon -i -odi -oem -oi -t -f jwakely

They all have start times that are a multiple of 5 minutes, so they must be coming from my cron job that runs every 5 minutes.

It looks like the MAILTO output of cron is failing to deliver, spitting an error into /var/log/messages, and then just retrying over and over.

This isn't a custom setup, just a fairly standard F23 installation less than 2 months old.

Comment 6 Jonathan Wakely 2016-02-24 20:34:29 UTC

[root@knitphad ~]# ls -lrt ~jwakely/.esmtp_queue/ | wc -l 
7185
[root@knitphad ~]# ls -lrt ~jwakely/.esmtp_queue/ | tail
drwx------. 2 jwakely jwakely 4096 Feb 24 19:45 fKdnrqYG
drwx------. 2 jwakely jwakely 4096 Feb 24 19:50 JDL4E07U
drwx------. 2 jwakely jwakely 4096 Feb 24 19:55 ZIJOeTKN
drwx------. 2 jwakely jwakely 4096 Feb 24 20:00 iEYvuK7E
drwx------. 2 jwakely jwakely 4096 Feb 24 20:05 J4jxsPii
drwx------. 2 jwakely jwakely 4096 Feb 24 20:10 N6XANhe5
drwx------. 2 jwakely jwakely 4096 Feb 24 20:15 FKzSJy8u
drwx------. 2 jwakely jwakely 4096 Feb 24 20:20 jE8Y5aVb
drwx------. 2 jwakely jwakely 4096 Feb 24 20:25 r0cJd61W
drwx------. 2 jwakely jwakely 4096 Feb 24 20:30 Eo35CFsR
[root@knitphad ~]# ls -lrt ~jwakely/.esmtp_queue/Eo35CFsR
total 4
-rw-r--r--. 1 jwakely jwakely 44 Feb 24 20:30 cmd
[root@knitphad ~]# cat ~jwakely/.esmtp_queue/Eo35CFsR/cmd 
-FCronDaemon -i -odi -oem -oi -t -f jwakely

Comment 7 Jonathan Wakely 2016-02-24 20:37:00 UTC

[root@knitphad ~]# ls ~jwakely/.esmtp_queue/*/mail
ls: cannot access /home/jwakely/.esmtp_queue/*/mail: No such file or directory

Comment 8 Brandon Ingalls 2016-03-13 02:14:34 UTC

I deleted the folder from my home folder earlier today and it recreated it...

[~]$ ls ~/.esmtp_queue | wc -l
334

I too have a cronjob that runs every 5 minutes, on a standard build of Fedora 23.

Comment 9 Murty Rompalli 2016-06-14 21:52:47 UTC

I created a small patch for the shell script: /usr/bin/esmtp-wrapper.
Basically:

1. Add the following 2 lines at the top of script:

ID=`id -un`
[ "$HOME" ] || HOME=`getent passwd $ID | cut -d: -f6`

2. Delete </dev/stdin

3. Inside case statement block: change return 1 to exit 1

Here is the diff output

$  diff /usr/bin/esmtp-wrapper /usr/bin/esmtp-wrapper.orig 
19,21d18
< ID=`id -un`
< [ "$HOME" ] || HOME=`getent passwd $ID | cut -d: -f6`
< 
39c36
<       cat  > "$mdir/mail" || ret=1
---
>       cat </dev/stdin >"$mdir/mail" || ret=1
86c83
<               queue_mail "$@" || exit 1
---
>               queue_mail "$@" || return 1

Comment 10 Jaroslav Škarvada 2016-06-14 22:34:08 UTC

(In reply to Murty Rompalli from comment #9)
> I created a small patch for the shell script: /usr/bin/esmtp-wrapper.

Thanks.

> Basically:
> 
> 1. Add the following 2 lines at the top of script:
> 
> ID=`id -un`
> [ "$HOME" ] || HOME=`getent passwd $ID | cut -d: -f6`
> 
Or we could add mailnull user as sendmail has and spool the mail to /var/spool/mqueue.

> 2. Delete </dev/stdin

I wonder why this doesn't work, SELinux? Could you try with 'setenforce 0'? Nevertheless it should work without it.

> 
> 3. Inside case statement block: change return 1 to exit 1

This seems to be upstream typo.

Comment 11 Murty Rompalli 2016-06-14 22:43:25 UTC

Given that esmtp is used for lightweight purposes, I prefer to use $HOME instead of /var/spool/mqueue.  Why bother creating mailnull or permissions on /var/spool/mqueue :)

Already tried with SELinux. I am one of those people who disables SELinux right away :)

I think Linux is using some fancy pipe and/or socket combo now, which messes up timing, so reading from /dev/stdin works for root only. Most likely, permissions aren't handed over properly by the time we read /dev/stdin.

Again, a determined soul can sort through /proc/self/fd/ mess.  Again, why bother?  Just skip /dev/stdin altogether and Linux will figure out how to handle piping output into esmpt-wrapper.

Comment 12 David Kaspar // Dee'Kej 2016-07-15 10:39:05 UTC

This has been annoying me for over a year now. Could we please get it fix? :) I guess less unnecessary logging will be also more evironment-friendly... ^_^

Comment 13 Jaroslav Škarvada 2016-07-18 10:11:12 UTC

(In reply to David Kaspar [Dee'Kej] from comment #12)
> This has been annoying me for over a year now. Could we please get it fix?
> :) I guess less unnecessary logging will be also more evironment-friendly...
> ^_^

Sorry, I forgot about it :)

Comment 14 Fedora Update System 2016-07-18 12:43:08 UTC

esmtp-1.2-3.fc24 has been submitted as an update to Fedora 24. https://bodhi.fedoraproject.org/updates/FEDORA-2016-772cdb1661

Comment 15 Fedora Update System 2016-07-18 12:53:44 UTC

esmtp-1.0-15.fc23 has been submitted as an update to Fedora 23. https://bodhi.fedoraproject.org/updates/FEDORA-2016-fd7708db05

Comment 16 Fedora Update System 2016-07-18 22:24:03 UTC

esmtp-1.0-15.fc23 has been pushed to the Fedora 23 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-fd7708db05

Comment 17 Fedora Update System 2016-07-18 22:25:26 UTC

esmtp-1.2-3.fc24 has been pushed to the Fedora 24 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-772cdb1661

Comment 18 Jonathan Wakely 2016-07-21 12:57:04 UTC

Looks like I'm now getting errors for trying to send mail to root:

Jul 21 13:51:49 knitphad audit: AVC avc:  denied  { read } for  pid=26234 comm="esmtp" path="/.esmtp_queue/7Ggn3Ecq/mail" dev="dm-1" ino=1835032 scontext=system_u:system_r:system_mail_t:s0-s0:c0.c1023 tcontext=system_u:object_r:root_t:s0 tclass=file permissive=0
Jul 21 13:51:54 knitphad audit: AVC avc:  denied  { read } for  pid=26238 comm="esmtp" path="/.esmtp_queue/9Vi4mYHQ/mail" dev="dm-1" ino=1835026 scontext=system_u:system_r:system_mail_t:s0-s0:c0.c1023 tcontext=system_u:object_r:root_t:s0 tclass=file permissive=0
Jul 21 13:51:59 knitphad audit: AVC avc:  denied  { read } for  pid=26242 comm="esmtp" path="/.esmtp_queue/tgd0FXAd/mail" dev="dm-1" ino=1835035 scontext=system_u:system_r:system_mail_t:s0-s0:c0.c1023 tcontext=system_u:object_r:root_t:s0 tclass=file permissive=0
Jul 21 13:52:04 knitphad audit: AVC avc:  denied  { read } for  pid=26247 comm="esmtp" path="/.esmtp_queue/xRoZWiqJ/mail" dev="dm-1" ino=1835029 scontext=system_u:system_r:system_mail_t:s0-s0:c0.c1023 tcontext=system_u:object_r:root_t:s0 tclass=file permissive=0

This can be easily reproduced by running (as root):

  echo echo test | at now

Comment 19 Fedora Update System 2016-07-27 18:54:27 UTC

esmtp-1.2-3.fc24 has been pushed to the Fedora 24 stable repository. If problems still persist, please make note of it in this bug report.

Comment 20 Fedora Update System 2016-07-27 20:52:34 UTC

esmtp-1.0-15.fc23 has been pushed to the Fedora 23 stable repository. If problems still persist, please make note of it in this bug report.

Comment 21 Ondřej Lysoněk 2016-08-11 08:03:08 UTC

*** Bug 1321465 has been marked as a duplicate of this bug. ***

Comment 22 Ondřej Lysoněk 2016-08-11 08:06:16 UTC

*** Bug 1256851 has been marked as a duplicate of this bug. ***

Comment 23 Ondřej Lysoněk 2016-08-11 08:08:51 UTC

*** Bug 1362685 has been marked as a duplicate of this bug. ***

Comment 24 Ondřej Lysoněk 2016-08-11 08:52:58 UTC

*** Bug 1149164 has been marked as a duplicate of this bug. ***

Comment 25 Ondřej Lysoněk 2016-08-11 08:59:18 UTC

*** Bug 1046468 has been marked as a duplicate of this bug. ***

Comment 26 Fedora Update System 2016-10-05 22:24:15 UTC

esmtp-1.2-4.fc25 has been pushed to the Fedora 25 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-4878f7323a

Comment 27 Fedora Update System 2016-10-06 01:50:29 UTC

esmtp-1.0-16.fc23 has been pushed to the Fedora 23 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-8991b160df

Comment 28 Fedora Update System 2016-10-06 01:51:42 UTC

esmtp-1.2-4.fc24 has been pushed to the Fedora 24 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-504e9109a8

Comment 29 Fedora Update System 2016-10-09 18:50:05 UTC

esmtp-1.2-4.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.

Comment 30 Fedora Update System 2016-10-09 22:20:45 UTC

esmtp-1.2-4.fc24 has been pushed to the Fedora 24 stable repository. If problems still persist, please make note of it in this bug report.

Comment 31 Fedora Update System 2016-10-14 01:20:25 UTC

esmtp-1.0-16.fc23 has been pushed to the Fedora 23 stable repository. If problems still persist, please make note of it in this bug report.

Comment 32 Eike Rathke 2016-10-24 13:47:55 UTC

With esmtp-1.2-4.fc24 I still have /root/.esmtp_queue/ filling up with cronjob mail and /var/spool/mail/root never created. Easily reproducible as root with

echo echo test | at now

Any configuration to change?

Comment 33 Ondřej Lysoněk 2016-10-27 07:30:15 UTC

You need to configure esmtp for local delivery. If you haven't made any configuration changes to esmtp, then installing the package 'esmtp-local-delivery' should do it. After installing it, if you send mail to root, it should all get flushed to /var/mail.

Comment 34 Eike Rathke 2016-10-27 14:29:58 UTC

Installing esmtp-local-delivery indeed fixed it. That should had been done by the initial install though.. (fresh install of F24 on this machine). Now mails are delivered to the user with id 1000 in /var/spool/mail/
Thanks.

Note You need to log in before you can comment on or make changes to this bug.