Antivirus failing to start in scripted restart

[dwmtractor]

I use the "Simple Shell Script" backup method, which among other things stops Zimbra services at night while doing a rsync of the files, then restarts them. We've had to mess with the syntax a few times since I first wrote the script due to some changes in Zimbra code; at present my stop and start commands in the script are:

su - zimbra -c "/opt/zimbra/bin/zmcontrol stop"
su - zimbra -c "/opt/zimbra/bin/zmcontrol start"

Since I have upgraded to 5.0.18 almost two weeks ago I have had it stop and restart successfully most days, but three times (last night being the third), antivirus services failed to start, resulting in a frozen mail queue. All three times, a manual stop and restart (plain-vanilla zmcontrol stop and zmcontrol start as Zimbra user) has brought everything back up with no errors, and the deferred mail scans and comes through.

Thinking the scripting might be the problem, I just tried running a stop and start from script (as root, not as Zimbra user) and everything restarted just fine this way too. I guess that shouldn't be a surprise since 10 times out of 13 it was fine overnight too.

I'm at a loss to know where to look for problems on this. /var/log/zimbra.log shows that antivirus never successfully started after last night's restart, but I can't actually find a reason. I hesitate to post the whole log, as it has ip addresses and email addresses I'd rather not have out in the public. However, if anyone can tell me specific entries I should look for/post, I can obfuscate them and put them up. Other debugging methods welcome too.

Thanks in advance. . .

[phoenix]

Have you tried running it with sudo (as mentioned on the wiki page) like this:

sudo -u zimbra zmcontrol start

[uxbod]

After the stop has been performed can you put in a ps aux and send that to a logfile. Would be interested to see whether all the AmavisD and Clam processes are actually stopping.

[dwmtractor]

Originally Posted by uxbod

After the stop has been performed can you put in a ps aux and send that to a logfile. Would be interested to see whether all the AmavisD and Clam processes are actually stopping.

I thought that'd be interesting too. . . So I did, and no, they weren't. Just because I wasn't sure I was remembering the ps syntax, I also checked the "Running Processes" page on my Webmin (which used to show the orphaned processes when I had them) and there was nothing even remotely Zimbra-related that was orphaned. That problem, at least, is resolved. . .

[dwmtractor]

Originally Posted by phoenix

Have you tried running it with sudo (as mentioned on the wiki page) like this:

sudo -u zimbra zmcontrol start

For reasons I've never understood, doing it with sudo has never worked for me, perhaps because I'm running Ubuntu and already sudo'ing bash to get to the root prompt? Anyway, since it doesn't always fail (but only occasionally) I doubt that the su-vs-sudo could be the issue, and if it were, I'm not sure how I'd verify it since it doesn't fail consistently.

I traded pms with Mike earlier this morning, and he noticed in my clamd.log:

Tue Jul 21 22:01:37 2009 -> --- Stopped at Tue Jul 21 22:01:37 2009
Tue Jul 21 22:04:34 2009 -> +++ Started at Tue Jul 21 22:04:34 2009
Tue Jul 21 22:04:34 2009 -> clamd daemon 0.95.1-broken-compiler (OS: linux-gnu, ARCH: i386, CPU: i686)
Tue Jul 21 22:04:34 2009 -> Log file size limited to 20971520 bytes.
Tue Jul 21 22:04:34 2009 -> Reading databases from /opt/zimbra/data/clamav/db
Tue Jul 21 22:04:34 2009 -> Not loading PUA signatures.
LibClamAV Error: cli_load(): Can't open file /opt/zimbra/data/clamav/db/main.cvd
Tue Jul 21 22:05:02 2009 -> ERROR: Can't open file or directory

Interestingly, the filename that throws the error doesn't even exist, which leads me to suspect a syntax error, though again why it works some times but not others, I don't know:

root@mail:/opt/zimbra/data/clamav/db# ls -l
total 49820
-rw-r----- 1 zimbra zimbra   348160 2008-10-26 22:05 clamav-993a64a7d6f0432d89f853e25
550dc71
-rw-r----- 1 zimbra zimbra  3517440 2009-07-22 09:00 daily.cld
-rw-r----- 1 zimbra zimbra 47079936 2009-07-21 22:04 main.cld
-rw------- 1 zimbra zimbra      780 2009-07-22 09:00 mirrors.dat
root@mail:/opt/zimbra/data/clamav/db#

What the issue is between main.cvd and main.cld as a filename, I don't know either, but methinks that can't be right. . .

[uxbod]

Have you tried http://wiki.zimbra.com/index.php?tit..._Reset_Defs_DB ?

[dwmtractor]

Originally Posted by uxbod

Have you tried ClamAV - Reset Defs DB - Zimbra :: Wiki ?

I thought about it, but since I'm not getting the errors that usually come with that problem, and particularly since a manual restart has Clam coming right up, I doubt that is the issue so I have not done so.

[uxbod]

Hmmm, you could try increasing the logging level performed by amavis. Update /opt/zimbra/conf/amavisd.conf.in and set log_level to say 3. This will increase the size of your logfiles though !

And perhaps run the zmcontrol start with sh -x zmcontrol start to see where it is hanging.

[dmmincrjr]

I have been seeing this problem since January. The only solution I have come up with is to use a script from this thread to restart the service. Antivirus Crashing nightly Maybe this thread also might offer some more clues to the mystery. I have upgraded to 5.0.18 and have noticed antivirus failing to start more frequently after being shut down for the backup as it has failed 9 of the last 14 times. I also looked in my clamd.log and have the same message about not being able to open main.cvd. If I remember correctly I think the problem also happened once after I rebooted the machine and had to manually stop and start zimbra to get mail flowing. I am using the ZCS Tools zimbraColdBackup script.

[dwmtractor]

I was kicking some ideas around with Mike Morse on this, and his idea of a workaround was to put a symlink in /opt/zimbra/data/clamav/db/ linking main.cvd (the nonexistent filename) to main.cld (the file that's actually there). I tried this last night, and for the first time in weeks clamav started without an error (I'll post logs below).

However, I notice that the symlink also got deleted last night when I did a restart of the clamav system via a cron'ed batch 20 minutes later.

It appears that something is calling a nonexistent file and bombing, however. See post below for more details.