amavis[12345]: (12345-02) (!)file utility failed: exit 1

[Michael Grimm]

Hi Marc --

On 23.10.2013, at 16:49, Mark Martinec <Mark.Martinec+freebsd at ijs.si> wrote:

>> amavis[12345]: (12345-02) (!)file utility failed: exit 1
>> 
>> 1. Do others see those warning messages as well, running the combination
>> amavisd-new 2.8.0 and file 5.15? 2. Can one safely ignore those messages?
> 
> If it occurs on a rare occasion, it is probably safe to ignore,
> otherwise it would be worth investigating.

It is happening on every single mail passing amavisd. 

> Other option is to enable debug logging (e.g. '# amavisd debug'),
> and grep for 'result line from file' in the log.

Here is the log file's excerpt for a plain ASCII mail message with 1000 'x' 
in the body, sent to an echo mailer:

| (50329-01) Issued a new file name: p001
| (50329-01) Charging 1000 bytes to remaining quota 792500 (out of 792500, (0%)) - by mime_decode
| (50329-01) p001 1 Content-Type: text/plain, size: 1000 B, name: 
| (50329-01) get_deadline mime_decode - deadline in 270.0 s, set to 189.000 s
| (50329-01) prolong_timer mime_decode: timer 189, was 189, deadline in 270.0 s
| (50329-01) get_deadline mime_decode-1 - deadline in 270.0 s, set to 189.000 s
| (50329-01) prolong_timer mime_decode-1: timer 189, was 189, deadline in 270.0 s
| (50329-01) inspect_dsn: parts: text/plain
| (50329-01) inspect_dsn: not a bounce
| (50329-01) get_deadline dsn_parse - deadline in 270.0 s, set to 189.000 s
| (50329-01) prolong_timer dsn_parse: timer 189, was 189, deadline in 270.0 s
| (50329-01) decode_parts: level=1, #parts=1 : p001
| (50329-01) running file(1) on 1 files, arglist size 24
| (50329-01) run_command: [3984] /usr/local/bin/file p001 </dev/null 2>&1
| (50329-01) result line from file(1): p001: ERROR: line 163: regex error 17, (illegal byte sequence)\n
| (50329-01) lookup_re("ERROR: line 163: regex error 17, (illegal byte sequence)") matches key "(?^:^ERROR:)", result="dat"
| (50329-01) lookup [map_full_type_to_short_type] => true,  "ERROR: line 163: regex error 17, (illegal byte sequence)" matches, result="dat", matching_key="(?^:^ERROR:)"
| (50329-01) File-type of p001: ERROR: line 163: regex error 17, (illegal byte sequence); (dat)
| (50329-01) (!)file utility failed: exit 1

Well, I have to admit: The interpretation of those lines are far beyond my scope ...

Questions:

1) Is the file utility to blame?
2) My setup?
3) What else might I do to investigate this issue?

>> 3. May "$file = '/usr/bin/file';" in amavisd.conf function as a valid
>> workaround for the time being? (I have to admit that I didn't dare testing
>> that, yet)
> 
> Yes, that is certainy a viable option.

After activating that option, and testing with "amavisd debug" as outlined
above, I'll get:

| (71656-01) Issued a new file name: p001
| (71656-01) Charging 1000 bytes to remaining quota 792500 (out of 792500, (0%)) - by mime_decode
| (71656-01) p001 1 Content-Type: text/plain, size: 1000 B, name: 
| (71656-01) get_deadline mime_decode - deadline in 270.0 s, set to 189.000 s
| (71656-01) prolong_timer mime_decode: timer 189, was 189, deadline in 270.0 s
| (71656-01) get_deadline mime_decode-1 - deadline in 270.0 s, set to 189.000 s
| (71656-01) prolong_timer mime_decode-1: timer 189, was 189, deadline in 270.0 s
| (71656-01) inspect_dsn: parts: text/plain
| (71656-01) inspect_dsn: not a bounce
| (71656-01) get_deadline dsn_parse - deadline in 270.0 s, set to 189.000 s
| (71656-01) prolong_timer dsn_parse: timer 189, was 189, deadline in 270.0 s
| (71656-01) decode_parts: level=1, #parts=1 : p001
| (71656-01) running file(1) on 1 files, arglist size 18
| (71656-01) run_command: [71668] /usr/bin/file p001 </dev/null 2>&1
| (71656-01) result line from file(1): p001: ASCII text\n

JYFI and with kind regards,
Michael