Amavisd does not start

[Paul Howarth]

Chris Jones wrote:
> Alexander Dalloz wrote:
>> Chris Jones schrieb:
>>
>>> Alexander Dalloz wrote:
>>>
>>>>> ... and here is the log fragment for that start:
>>>>> Jul 20 18:27:41 bilbo amavis[7120]: starting.  /usr/sbin/amavisd at 
>>>>> bilbo.stow-jones.local amavisd-new-2.4.1 (20060508), Unicode aware, 
>>>>> LANG=en_US.UTF-8
>>>>> Jul 20 18:27:41 bilbo amavis[7120]: Perl version               
>>>>> 5.008008
>>>>
>>>>
>>>> Nothing more appears at amavisd start time? Normally quite a few 
>>>> tests would run, about the Perl environment / helper modules, 
>>>> anti-virus scanners, spamassassin ...
>>>>
>>> No. That is all that occurs.
>>
>> Ok. Not good. Then amavisd ends at a very early point.
>>
>>>> Time to get a hand at /etc/amavisd.conf. It has an option to not use 
>>>> sylog for logging but an own file. Use that in combination with a 
>>>> higher debug level.
>>>
>>> $DO_SYSLOG = 1;              # log via syslogd (preferred)
>>>
>>> What level should I set to increase the logging?
>>
>> The maximum debug level is "5". Be not shocked to see a lot of 
>> information, but that is its purpose.
>>
>>>> Do you have SELinux being enforced?
>>>
>>> Yes
>>
>> Then for a quick test I would switch into permissive mode, to see if 
>> that is the culprit. You too could have a look at /var/log/messages or 
>> if auditd runs at /var/log/audit/audit.log to watch auth for amavisd 
>> related avc / audit messages.
> I already had audit switched on (to solve a previous issue some weeks 
> ago). Here is the result of an attempt to stop amavisd having 
> successfully started it following Justin's suggestion.
> 
> type=AVC msg=audit(1153425626.139:348): avc:  denied  { read write } 
> for  pid=8158 comm="amavisd" name="1" dev=devpts ino=3 
> scontext=user_u:system_r:amavis_t:s0 
> tcontext=user_u:object_r:devpts_t:s0 tclass=chr_file
> type=AVC msg=audit(1153425626.139:348): avc:  denied  { read write } 
> for  pid=8158 comm="amavisd" name="1" dev=devpts ino=3 
> scontext=user_u:system_r:amavis_t:s0 
> tcontext=user_u:object_r:devpts_t:s0 tclass=chr_file
> type=AVC msg=audit(1153425626.139:348): avc:  denied  { read write } 
> for  pid=8158 comm="amavisd" name="1" dev=devpts ino=3 
> scontext=user_u:system_r:amavis_t:s0 
> tcontext=user_u:object_r:devpts_t:s0 tclass=chr_file
> type=AVC msg=audit(1153425626.139:348): avc:  denied  { read write } 
> for  pid=8158 comm="amavisd" name="1" dev=devpts ino=3 
> scontext=user_u:system_r:amavis_t:s0 
> tcontext=user_u:object_r:devpts_t:s0 tclass=chr_file
> type=SYSCALL msg=audit(1153425626.139:348): arch=c000003e syscall=59 
> success=yes exit=0 a0=6ee2d0 a1=6c9d00 a2=6c89a0 a3=8 items=3 pid=8158 
> auid=500 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 
> comm="amavisd" exe="/usr/bin/perl"
> type=AVC_PATH msg=audit(1153425626.139:348):  path="/dev/pts/1"
> type=AVC_PATH msg=audit(1153425626.139:348):  path="/dev/pts/1"
> type=AVC_PATH msg=audit(1153425626.139:348):  path="/dev/pts/1"
> type=CWD msg=audit(1153425626.139:348):  cwd="/"
> type=PATH msg=audit(1153425626.139:348): item=0 name="/usr/sbin/amavisd" 
> flags=101  inode=23835933 dev=fd:00 mode=0100755 ouid=0 ogid=0 rdev=00:00
> type=PATH msg=audit(1153425626.139:348): item=1 flags=101  
> inode=23828297 dev=fd:00 mode=0100755 ouid=0 ogid=0 rdev=00:00
> type=PATH msg=audit(1153425626.139:348): item=2 flags=101  
> inode=23003181 dev=fd:00 mode=0100755 ouid=0 ogid=0 rdev=00:00
> type=AVC msg=audit(1153425626.147:349): avc:  denied  { search } for  
> pid=8158 comm="amavisd" scontext=user_u:system_r:amavis_t:s0 
> tcontext=system_u:object_r:sysctl_kernel_t:s0 tclass=dir
> type=SYSCALL msg=audit(1153425626.147:349): arch=c000003e syscall=156 
> success=no exit=-1 a0=7fffffbc93e0 a1=0 a2=0 a3=347f347cc0 items=0 
> pid=8158 auid=500 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 
> fsgid=0 comm="amavisd" exe="/usr/bin/perl"
> type=AVC msg=audit(1153425627.555:350): avc:  denied  { getattr } for  
> pid=8158 comm="amavisd" name="amavisd.pid" dev=dm-0 ino=34767186 
> scontext=user_u:system_r:amavis_t:s0 
> tcontext=user_u:object_r:var_run_t:s0 tclass=file
> type=SYSCALL msg=audit(1153425627.555:350): arch=c000003e syscall=4 
> success=no exit=-13 a0=8c5fe0 a1=504140 a2=504140 a3=0 items=1 pid=8158 
> auid=500 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 
> comm="amavisd" exe="/usr/bin/perl"
> type=AVC_PATH msg=audit(1153425627.555:350):  
> path="/var/run/amavisd/amavisd.pid"
> type=CWD msg=audit(1153425627.555:350):  cwd="/"
> type=PATH msg=audit(1153425627.555:350): item=0 
> name="/var/run/amavisd/amavisd.pid" flags=1  inode=34767186 dev=fd:00 
> mode=0100640 ouid=101 ogid=501 rdev=00:00
> 
> It does look as though this has something to do with SELinux being set 
> to Enforcing.
> 
> I have now set SELinux to permissive and (lo and behold) the commands 
> 'service amavisd start' and 'service amavisd stop' both work as intended.
> 
> Is this behaviour when SELinux is set to Enforcing correct? Or is this a 
> bug that needs to be addressed?

It is a bug, probably due to changes in SELinux; I suspect that the 
current amavis would have worked with older SELinux policies.

> Following on from this, and based upon the fact that my FC5 box is only 
> a personal "toy" system so that I can learn Linux properly, should I be 
> concerned about SELinux being set to "permissive"?

You could view it as a good opportunity to start learning about SELinux :-)

Probably the best place to raise this and get it fixed would be 
fedora-selinux-list. You might also want to have a go at fixing it 
yourself, and if you succeed, you could mention that when you post to 
the SELinux list.

Here's a brief intro to fixing SELinux problems in FC5:
http://www.city-fan.org/tips/BuildSeLinuxPolicyModules

Paul.