Mails misclassified from vBulletin Forum Software

[Joerg Rohrer]

Thanks Adreas

On 10-09-2014 13:23, A. Schulze wrote:
> Joerg Rohrer:
> 
>> Any ideas were i could start debugging?
> set $log_level = 5;
> 
> if impossible ( too much log ) try @debug_sender_maps or 
> @debug_recipient_maps
> 
> Andreas

Below the relevant part.

Sep 10 15:21:00 alpha amavis[8825]: (08825-01) Extracting mime 
components from a string
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) Issued a new file name: 
p001
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) Charging 4518 bytes to 
remaining quota 2751500 (out of 2751500, (0%)) - by mime_decode
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) p001 1 Content-Type: 
text/plain, size: 4518 B, name:
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) get_deadline mime_decode 
- deadline in 480.0 s, set to 336.000 s
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) prolong_timer 
mime_decode: timer 336, was 336, deadline in 480.0 s
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) get_deadline 
mime_decode-1 - deadline in 480.0 s, set to 336.000 s
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) prolong_timer 
mime_decode-1: timer 336, was 336, deadline in 480.0 s
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) decode_parts: level=1, 
#parts=1 : p001
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) running file(1) on 1 
files, arglist size 18
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) run_command: [8841] 
/usr/bin/file p001 </dev/null 2>&1
Sep 10 15:21:00 alpha amavis[8841]: (08825-01) open_on_specific_fd: 
target fd0 closing, to become < /dev/null
Sep 10 15:21:00 alpha amavis[8841]: (08825-01) open_on_specific_fd: 
target fd1 closing, to become (65) &=15
Sep 10 15:21:00 alpha amavis[8841]: (08825-01) open_on_specific_fd: 
target fd1 dup2 from fd15 (65) &=15
Sep 10 15:21:00 alpha amavis[8841]: (08825-01) open_on_specific_fd: 
source fd15 closed
Sep 10 15:21:00 alpha amavis[8841]: (08825-01) open_on_specific_fd: 
target fd2 closing, to become (65) &1
Sep 10 15:21:00 alpha amavis[8841]: (08825-01) open_on_specific_fd: 
target fd2 dup2 from fd1 (65) &1
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) result line from file(1): 
p001: Python script, UTF-8 Unicode text executable\n
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) lookup_re("Python script, 
UTF-8 Unicode text executable") matches key "(?^i:\bexecutable\b)", 
result="exe"
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) lookup 
[map_full_type_to_short_type] => true,  "Python script, UTF-8 Unicode 
text executable" matches, result="exe", 
matching_key="(?^i:\134bexecutable\134b)"
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) File-type of p001: Python 
script, UTF-8 Unicode text executable; (exe)
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) Check whether p001 is a 
self-extracting archive
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) Unzipping p001
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) do_unzip: ok, exe is not 
a zip sfx: AZ_FORMAT_ERROR (3)
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) Expanding RAR archive 
p001
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) get_deadline do_unrar_pre 
- deadline in 479.9 s, set to 336.000 s
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) prolong_timer 
do_unrar_pre: timer 336, was 336, deadline in 479.9 s
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) run_command: [8842] 
/usr/bin/unrar v -c- -p- -idcdp -- 
/mnt/amavis/amavis-20140910T152100-08825-y8EH73zE/parts/p001 </dev/null 
2>&1
Sep 10 15:21:00 alpha amavis[8842]: (08825-01) open_on_specific_fd: 
target fd0 closing, to become < /dev/null
Sep 10 15:21:00 alpha amavis[8842]: (08825-01) open_on_specific_fd: 
target fd1 closing, to become (65) &=15
Sep 10 15:21:00 alpha amavis[8842]: (08825-01) open_on_specific_fd: 
target fd1 dup2 from fd15 (65) &=15
Sep 10 15:21:00 alpha amavis[8842]: (08825-01) open_on_specific_fd: 
source fd15 closed
Sep 10 15:21:00 alpha amavis[8842]: (08825-01) open_on_specific_fd: 
target fd2 closing, to become (65) &1
Sep 10 15:21:00 alpha amavis[8842]: (08825-01) open_on_specific_fd: 
target fd2 dup2 from fd1 (65) &1
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) get_deadline do_unrar - 
deadline in 479.9 s, set to 336.000 s
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) prolong_timer do_unrar: 
timer 336, was 336, deadline in 479.9 s
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) do_executable: not a RAR 
sfx, ignoring: do_unrar: 
/mnt/amavis/amavis-20140910T152100-08825-y8EH73zE/parts/p001 is not RAR 
archive at (eval 147) line 901.
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) do_executable: not an ARJ 
sfx, ignoring: do_unrar: 
/mnt/amavis/amavis-20140910T152100-08825-y8EH73zE/parts/p001 is not RAR 
archive at (eval 147) line 901.
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) decompose_part: p001 - 
atomic
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) get_deadline parts_decode 
- deadline in 479.9 s, set to 336.000 s
Sep 10 15:21:00 alpha amavis[8825]: (08825-01) prolong_timer 
parts_decode: timer 336, was 336, deadline in 479.9 s

Regards
Jörg