amavisd-new broken after update, permissions issue [SOLVED]

[epig]

Hi all,

Updated my amavisd-new this morning and it broke somehow.

Now, in the /var/log/mail/current, there is no trace of the usual startup logging. Zip, Zilch. Nada.
Starting the service returns an OK, but no processes spawn.

Starting just the binary, however, returns:

Code: Select all

grond ~ # amavisd
Error reading config file "/etc/amavisd.conf": Permission denied at /usr/sbin/amavisd line 2238.

Version info:

amavisd-new-2.12.2 (20211013)


with no logging, I am stumped...

Anyone have a pointer or two?

[epig]

Upon further investigation, it seems that the update had taken away all read rights in the /etc/amavisd.conf file.

Code: Select all

 # ls -lah /etc/amavisd.conf
-rwx------ 1 root 206 116K Feb 28 13:19 /etc/amavisd.conf

So after running a

Code: Select all

chmod 744 /etc/amavisd.conf

the permissions seem to work OK and the service starts just fine:

Code: Select all

 # ls -lah /etc/amavisd.conf
-rwxr--r-- 1 root 206 116K Feb 28 13:19 /etc/amavisd.conf

I thought I'd just leave it here, since osmeonw else might come across the same problem...

[freke]

Code: Select all

 # ls -lah /etc/amavisd.conf
-rwx------ 1 root 206 116K Feb 28 13:19 /etc/amavisd.conf

Unknown group-ownership?

[epig]

Code: Select all

 # ls -lah /etc/amavisd.conf
-rwx------ 1 root 206 116K Feb 28 13:19 /etc/amavisd.conf

Unknown group-ownership?

Could be, not sure.
Works after setting proper config file permissions, anyway.

[Hu]

Configuration files are normally not executable. 644 would be more traditional. Are you sure the file was world-readable before the update? It could be that the file was always mode 600, but that older versions of the script read the file while still running as root, and the new version changes to an unprivileged user before reading the file.

[epig]

Configuration files are normally not executable. 644 would be more traditional. Are you sure the file was world-readable before the update? It could be that the file was always mode 600, but that older versions of the script read the file while still running as root, and the new version changes to an unprivileged user before reading the file.

Yes, 644 is correct (and works). Let's call it a typo...
Could have been a change in permissions, but usually that shows up in the patch notes/package comments. Didn't see that here.

IF the file was 600, that no longer worked, so 644 it is.

[deagol]

Got bitten by the same issue: System updated bumped amavisd from 2.12.1 to 2.12.2. After the update the service was not working and calling it manually produced the exact same error as you got.

I'm sure the permission of /etc/amavisd.conf was not changed during the update, I still have the btrfs snapshot showing the old file permission:

Code: Select all

-rw-r-----. 1 root root system_u:object_r:amavis_etc_t 37118 Jan 14  2017 amavisd.conf

While debugging it I was able to link the problem to the first usage of $! in the line 2238 from /usr/sbin/amavisd:

Code: Select all

 elsif ($! != 0)  { die "Error reading config file \"$config_file\": $!" }

Commenting out that line worked, also changing the elsif to "0 != 0".

Now changing /etc/amavisd.conf to 644 also fixed the issue for me, It looks like for some strange. After all it looks like the usage of $! caused the error, there was no message that the config file was unreadable...

It's working now but if someone can explain the reason why I would be very interested...

[epig]

Commenting out that line worked, also changing the elsif to "0 != 0".

Now changing /etc/amavisd.conf to 644 also fixed the issue for me, It looks like for some strange. After all it looks like the usage of $! caused the error, there was no message that the config file was unreadable...

It's working now but if someone can explain the reason why I would be very interested...

Surely this must be a bug of some kind?

[Hu]

I could believe that the newer daemon switches to an unprivileged user early in startup.

Commenting out that line worked, also changing the elsif to "0 != 0".

Removing error handling usually does silence the error reporting.

Now changing /etc/amavisd.conf to 644 also fixed the issue for me, It looks like for some strange. After all it looks like the usage of $! caused the error, there was no message that the config file was unreadable...

That is exactly the message the OP reported at the start: Permission denied at /usr/sbin/amavisd line 2238.

[Duncan Mac Leod]

...will this be fixed in an updated ebuild ?

[figueroa]

Seriously, who/what is group 206? Fix that.

[Hu]

I'm sure the permission of /etc/amavisd.conf was not changed during the update, I still have the btrfs snapshot showing the old file permission:

Code: Select all

-rw-r-----. 1 root root system_u:object_r:amavis_etc_t 37118 Jan 14  2017 amavisd.conf

This is not the permissions that the OP reported. However, it is also not consistent with what the ebuild seems to set:

Code: Select all

    # The config file should be root:amavis so that the amavis user can
    # read (only) it after dropping privileges. And of course he should
    # own everything in his home directory.
    insinto /etc
    insopts -m0640 -g amavis
    doins amavisd.conf

...will this be fixed in an updated ebuild ?

Is there an open bug report that describes what needs to be changed?

[MoonWalker]

Ok ran in to this as well, so bringing the topic back to life. Still haven't got it working, so will make a try here incase someone got to it w/o sharing the solution. Here is some output from my box:

merc # /etc/init.d/amavisd restart
* Stopping amavisd ...
* start-stop-daemon: no matching processes found [ ok ]
* Starting amavisd ... [ ok ]
merc # /etc/init.d/amavisd status
* status: crashed
merc # ls -l /run/amavisd.pid
-rw-r--r-- 1 root root 6 Apr 4 16:02 /run/amavisd.pid
merc # ls -l /etc/amavisd.conf
-rw-r----- 1 root amavis 106574 Apr 16 2021 /etc/amavisd.conf
merc # ps aux | grep postfix
root 20589 0.0 0.0 50528 5820 ? Ss 13:58 0:00 /usr/libexec/postfix/master -w
postfix 20591 0.0 0.0 51732 9384 ? S 13:58 0:00 qmgr -l -t unix -u
postfix 20601 0.0 0.0 50732 9280 ? S 13:58 0:00 tlsmgr -l -t unix -u
postfix 23249 0.0 0.0 50552 6564 ? S 15:37 0:00 pickup -l -t fifo -u -o cleanup_service_name=pre-cleanup
postfix 23745 0.0 0.0 51348 12136 ? S 15:56 0:00 smtpd -n smtp -t inet -u -o stress= -o cleanup_service_name=pre-cleanup
postfix 23747 0.0 0.0 50552 6680 ? S 15:56 0:00 anvil -l -t unix -u
postfix 23944 0.0 0.0 50564 6552 ? S 16:03 0:00 trivial-rewrite -n rewrite -t unix -u
postfix 23945 0.0 0.0 50836 10520 ? S 16:03 0:00 proxymap -t unix -u
postfix 23960 0.0 0.0 51216 12112 ? S 16:04 0:00 smtpd -n smtp -t inet -u -o stress= -o cleanup_service_name=pre-cleanup
postfix 23961 0.0 0.0 51216 11228 ? S 16:04 0:00 smtpd -n submission -t inet -u -o stress= -o syslog_name=postfix/submission -o smtpd_tls_wrappermode=no -o smtpd_tls_security_level=encrypt -o smtpd_sasl_auth_enable=yes -o smtpd_sasl_type=dovecot -o smtpd_sasl_path=private/auth -o smtpd_sasl_security_options=noanonymous -o smtpd_sasl_local_domain=$myhostname -o smtpd_client_restrictions=permit_mynetworks,permit_sasl_authenticated,reject -o smtpd_sender_login_maps=proxy:mysql:$config_directory/sql/mysql_virtual_mailbox_maps.cf -o smtpd_sender_restrictions=reject_sender_login_mismatch -o smtpd_relay_restrictions=permit_mynetworks,permit_sasl_authenticated,reject_unauth_destination -o milter_macro_daemon_name=ORIGINATING
postfix 23962 0.0 0.0 50552 9360 ? Ss 16:04 0:00 verify -l -t unix -u
postfix 23963 0.0 0.0 51452 8936 ? S 16:04 0:00 cleanup -z -n pre-cleanup -t unix -u -o virtual_alias_maps= -o canonical_maps= -o sender_canonical_maps= -o recipient_canonical_maps= -o masquerade_domains=
postfix 23964 0.0 0.0 50968 10664 ? S 16:04 0:00 smtp -n smtp-amavis -t unix -u -o smtp_data_done_timeout=1200 -o smtp_send_xforward_command=yes -o disable_dns_lookups=yes -o max_use=20
postfix 23965 0.0 0.0 50584 6684 ? S 16:04 0:00 bounce -z -n defer -t unix -u
root 23988 0.0 0.0 6684 2040 pts/1 S+ 16:05 0:00 grep --colour=auto postfix
merc # ps aux | grep amavis
root 23235 0.0 0.0 8336 4788 pts/4 S+ 15:36 0:00 nano /etc/amavisd.conf
postfix 23964 0.0 0.0 50968 10664 ? S 16:04 0:00 smtp -n smtp-amavis -t unix -u -o smtp_data_done_timeout=1200 -o smtp_send_xforward_command=yes -o disable_dns_lookups=yes -o max_use=20
root 23993 0.0 0.0 6684 2172 pts/1 S+ 16:05 0:00 grep --colour=auto amavis
merc # /etc/init.d/amavisd stop
* Stopping amavisd ...
* start-stop-daemon: no matching processes found [ ok ]
merc # ls -l /run/amavisd.pid
ls: cannot access '/run/amavisd.pid': No such file or directory

merc is the name of my box.

Something strange is definitely going on as the pid is there but still no process according to ps. Also, after the update it stopped to write to /var/lib/amavishome/amavis.log nor is it recreated if removed. So apparently, something is stopping amavisd from starting for real.

I tried changing permissions on amavis.conf but it yielded nothing.

[Duncan Mac Leod]

Cannot confirm this!

Updated 4 Gentoo boxes, checked all files before and after installation.

No file permissions have been altered during installation...

[MoonWalker]

so your amavisd runs okay?

[MoonWalker]

I opened a bug for this issue:
https://bugs.gentoo.org/836768

[Duncan Mac Leod]

so your amavisd runs okay?

YES - runs without any issues.

[MoonWalker]

so your amavisd runs okay?

YES - runs without any issues.

Do you have a amavisd file in /etc/conf.d/ ?

I notice when running

# /etc/init.d/amavisd -d start

it check for a file there (which I don't have), but maybe it's just a general script check. I don't know.

# amavisd -d start
merc ~ # /etc/init.d/amavisd -d start
+ sourcex -e /etc/rc.conf
+ '[' -e = -e ']'
+ shift
+ '[' -e /etc/rc.conf ']'
+ . /etc/rc.conf
++ rc_shell=/sbin/sulogin
++ unicode=YES
++ rc_tty_number=12
+ '[' -d /etc/rc.conf.d ']'
+ _conf_d=/etc/init.d/../conf.d
+ _c=amavisd
+ '[' -n amavisd -a amavisd '!=' amavisd ']'
+ unset _c
+ sourcex -e /etc/init.d/../conf.d/amavisd.default
+ '[' -e = -e ']'
+ shift
+ '[' -e /etc/init.d/../conf.d/amavisd.default ']'
+ return 1
+ sourcex -e /etc/init.d/../conf.d/amavisd
+ '[' -e = -e ']'
+ shift
+ '[' -e /etc/init.d/../conf.d/amavisd ']'
+ return 1
+ unset _conf_d
+ sourcex /lib/rc/sh/runit.sh
+ '[' /lib/rc/sh/runit.sh = -e ']'
+ . /lib/rc/sh/runit.sh
+ sourcex /lib/rc/sh/s6.sh
+ '[' /lib/rc/sh/s6.sh = -e ']'
+ . /lib/rc/sh/s6.sh
++ '[' -z '' ']'
++ s6_service_path=/var/svc.d/amavisd
+ sourcex /lib/rc/sh/start-stop-daemon.sh
+ '[' /lib/rc/sh/start-stop-daemon.sh = -e ']'
+ . /lib/rc/sh/start-stop-daemon.sh
+ sourcex /lib/rc/sh/supervise-daemon.sh
+ '[' /lib/rc/sh/supervise-daemon.sh = -e ']'
+ . /lib/rc/sh/supervise-daemon.sh
++ extra_commands='healthcheck unhealthy '
+ sourcex /etc/init.d/amavisd
+ '[' /etc/init.d/amavisd = -e ']'
+ . /etc/init.d/amavisd
++ extra_started_commands=reload
++ command=/usr/sbin/amavisd
++ pidfile=/run/amavisd.pid
++ command_args=foreground
++ command_background=true
++ retry='SIGTERM/15 SIGKILL/60'
+ yesno ''
+ '[' -z '' ']'
+ return 1
+ for _cmd in "$@"
+ '[' start '!=' status -a start '!=' describe ']'
+ '[' -n '' ']'
++ command -v cgroup_add_service
+ '[' cgroup_add_service = cgroup_add_service ']'
+ grep -qs /sys/fs/cgroup /proc/1/mountinfo
+ '[' -d /sys/fs/cgroup -a '!' -w /sys/fs/cgroup ']'
+ cgroup_add_service
+ for d in /sys/fs/cgroup/*
+ '[' -w /sys/fs/cgroup/net_cls/tasks ']'
+ printf %d 0
+ for d in /sys/fs/cgroup/*
+ '[' -w /sys/fs/cgroup/openrc/tasks ']'
+ printf %d 0
+ for d in /sys/fs/cgroup/*
+ '[' -w /sys/fs/cgroup/unified/tasks ']'
+ openrc_cgroup=/sys/fs/cgroup/openrc
+ '[' -d /sys/fs/cgroup/openrc ']'
+ cgroup=/sys/fs/cgroup/openrc/amavisd
+ mkdir -p /sys/fs/cgroup/openrc/amavisd
+ '[' -w /sys/fs/cgroup/openrc/amavisd/tasks ']'
+ printf %d 0
++ command -v cgroup_set_limits
+ '[' cgroup_set_limits = cgroup_set_limits ']'
+ cgroup_set_limits
+ local blkio=
+ '[' -n '' ']'
+ local cpu=
+ '[' -n '' ']'
+ local cpuacct=
+ '[' -n '' ']'
+ local cpuset=
+ '[' -n '' ']'
+ local devices=
+ '[' -n '' ']'
+ local hugetlb=
+ '[' -n '' ']'
+ local memory=
+ '[' -n '' ']'
+ local net_cls=
+ '[' -n '' ']'
+ local net_prio=
+ '[' -n '' ']'
+ local pids=
+ '[' -n '' ']'
+ return 0
++ command -v cgroup2_set_limits
+ '[' cgroup2_set_limits = cgroup2_set_limits ']'
+ '[' start = start ']'
+ cgroup2_set_limits
+ local cgroup_path
++ cgroup2_find_path
++ grep -qw cgroup2 /proc/filesystems
++ case "${rc_cgroup_mode:-hybrid}" in
++ printf /sys/fs/cgroup/unified
++ return 0
+ cgroup_path=/sys/fs/cgroup/unified
+ '[' -z /sys/fs/cgroup/unified ']'
+ mountinfo -q /sys/fs/cgroup/unified
+ rc_cgroup_path=/sys/fs/cgroup/unified/amavisd
+ '[' '!' -d /sys/fs/cgroup/unified/amavisd ']'
+ mkdir /sys/fs/cgroup/unified/amavisd
+ '[' -f /sys/fs/cgroup/unified/amavisd/cgroup.procs ']'
+ printf 0
+ '[' -z '' ']'
+ return 0
+ break
+ eval 'printf '\''%s\n'\'' '
++ printf '%s\n'
+ read _d
+ '[' -n '' ']'
+ read _d
+ '[' 0 -ne 0 ']'
+ unset _d
+ eval 'printf '\''%s\n'\'' '
++ printf '%s\n'
+ read _f
+ '[' -n '' ']'
+ read _f
+ '[' 0 -ne 0 ']'
+ unset _f
+ '[' -n '' ']'
+ '[' -n start ']'
+ '[' start = depend ']'
+ for _cmd in describe start stop status ${extra_commands:-$opts} $extra_started_commands $extra_stopped_commands
+ '[' describe = start ']'
+ for _cmd in describe start stop status ${extra_commands:-$opts} $extra_started_commands $extra_stopped_commands
+ '[' start = start ']'
++ command -v start
+ '[' start = start ']'
+ yesno
+ '[' -z '' ']'
+ return 1
+ for _cmd in $extra_started_commands
+ '[' reload = start ']'
+ for _cmd in $extra_stopped_commands
+ '[' cgroup_cleanup = start ']'
+ unset _cmd
+ case $1 in
+ verify_boot
+ '[' '!' -e /run/openrc/softlevel ']'
+ return 0
++ command -v start_pre
+ '[' '' = start_pre ']'
+ start
+ default_start
+ local func=ssd_start
+ case "$supervisor" in
+ ssd_start
+ '[' -z /usr/sbin/amavisd ']'
+ local _background=
+ ebegin 'Starting amavisd'
* Starting amavisd ...
+ yesno true
+ '[' -z true ']'
+ case "$1" in
+ return 0
+ '[' -z /run/amavisd.pid ']'
+ '[' -n '' ']'
+ _background='--background --make-pidfile'
+ yesno ''
+ '[' -z '' ']'
+ return 1
+ '[' -n '' ']'
+ '[' -n '' ']'
+ eval start-stop-daemon --start --exec /usr/sbin/amavisd --pidfile /run/amavisd.pid --background --make-pidfile -- foreground
++ start-stop-daemon --start --exec /usr/sbin/amavisd --pidfile /run/amavisd.pid --background --make-pidfile -- foreground
+ eend 0 'Failed to start amavisd' [ ok ]
+ service_set_value command /usr/sbin/amavisd
+ '[' -n '' ']'
+ '[' -n /run/amavisd.pid ']'
+ service_set_value pidfile /run/amavisd.pid
+ '[' -n '' ']'
+ return 0
++ command -v start_post
+ '[' '' = start_post ']'
++ command -v cgroup_cleanup
+ '[' cgroup_cleanup = cgroup_cleanup ']'
+ '[' start = stop ']'
++ command -v cgroup2_remove
+ '[' cgroup2_remove = cgroup2_remove ']'
+ '[' start = stop ']'
+ '[' -z /usr/sbin/amavisd ']'
+ shift
+ continue 2
+ '[' -n '' ']'
+ exit 0

I'm not really able to read out what that output actually is saying, more than 'Failed to start amavisd' and not that I understand it, but something tells me that it may have something to do with cgroup, which I don't really know anything about.

[Duncan Mac Leod]

No, I don't have anything amavisd-new related under /etc/conf.d

my config file is: /etc/amavisd.conf

[MoonWalker]

Well, I am lost as it doesn't write anything to the log file as if it doesn't even try to start!
The only thing I can get out of the mail log is

Apr 04 22:16:02 [/etc/init.d/amavisd] start-stop-daemon: no matching processes found

but that doesn't come from amavisd as I have it configured to write to its own file.

It's probably some freaking small detail in my system but I cannot see it!

The only think that I possibly can think of is that I am still on profile 17.0, could that be it?

I'm in the process to upgrade, but not there yet.

[deagol]

Nothing new to the careful reader but I want to point out that the correct fix for the epig and also me was basically:

Code: Select all

  chgrp amavis /etc/amavisd.conf
  chmod 0640 /etc/amavisd.conf

This sets the permissions to what you would get when you install amavisd-new fresh nowadays.

Looks like up to 2.12.2 amavisd-new was still running as root when the config file was parsed and the "wrong" permissions were ok. Starting with 2.12.2 root gets dropped prior to parsing the config files and installations with the wrong permissions get issues.
Not nice but I would not rate that as a bug. This is just something which happens from time to time with rolling releases.

The bug here for me is, that the correct error message is too verbose. It would probably be more helpful to just get something like Error reading config file /etc/amavisd.conf

edit:
fixed incorrect statement about the error message. It's printed out

[MoonWalker]

Maybe my issue is different then because /etc/amavisd.conf permissions are as it should be.

merc ~ # ls -l /etc/amavisd.conf
-rw-r----- 1 root amavis 106574 Apr 4 22:31 /etc/amavisd.conf
merc ~ # /etc/init.d/amavisd restart
* Caching service dependencies ... [ ok ]
* Stopping amavisd ...
* start-stop-daemon: no matching processes found [ ok ]
* Starting amavisd ... [ ok ]
merc ~ # /etc/init.d/amavisd status
* status: crashed

EDIT: I also tried to change owner to amavis, but still no go.

It simply doesn't work, it simply doesn't try to start, it simply doesn't create any process and it simply doesn't write anything to the logs! However, it does create /run/amavisd.pid

And I simply have to wait and see if my opened bug yields any new insight and hopefully a solution. Fact is, it worked before I upgraded and as there is only 1 ebuild there is no way to downgrade - but also worth keeping in mind is that I also upgraded a batch of other packages at the same time and that may have something to do with it. Well as it works for others, it kind of has to be some external circumstance that is causing this.

BTW I also tried to make that edit in the /usr/sbin/amavisd file to no avail.

[MoonWalker]

Ok I am trying to take another approach to this by looking at the time stamp in the mail queue (using webmin) for the first email rejected by postfix w/

delivery temporarily suspended: connect to 127.0.0.1[127.0.0.1] Connection refused

and

connect to 127.0.0.1[127.0.0.1] Connection refused

that's the 2 error messages that shows up in the mail log, but it's from postfix and I know that's because amasivd isn't running.

But looking at these timestamps and also checking in the emerge.log file I have reached the somewhat embarrassing conclusion that this may not be a bug in amavis after all. Indeed, amavisd-new-2.12.2 was first installed om 3 March and this issue started after noon on the 31 March. I have then emerged it again only after that date. Fact remains though, emails are not delivered but queued up due to amavisd not starting/running.

I will dig deeper in the historic data to see if I can come up with a suspect, well basically dig out what was emerged ahead of mail deliveries stopped.

[MoonWalker]

how can I check if /usr/sbin/amavisd is even accessed ? I mean is there some code I can put that somehow confirms to me that it's accessed?

I mean, /usr/sbin/amavisd is perl, right?

[MoonWalker]

My investigation of the logs has revealed the following:

All on 31 March
at 12:14 I got my last email delivered to inbox
at 12:27 emerge update of glibc completed
at 12:31 the first bounce showed up in the mail queue.

So for a moment I though it could be a glibc "reboot needed" issue.

However, before a reboot I updated my kernel to 4.19.237 (from 4.19.28) as I have had issues rebooting remotely with the old kernel. I then rebooted my system remotely, successfully.
That didn't change the situation though, amavisd still refuses to start a process but creates a pid (as if it was running, which isn't the case).

I am now making a full #emerge --emptytree @world rebuild, and then I will change profile to 17.1 no-multilib and rebuild again.

If that doesn't solve it... I don't know what to do.