[Amavis-users] Incorrect content identification

[Kiss Gabor (Bitman)]

Dear Mark,

> > Apparently the file(1) utility misqualifies some part of these messages
> > as something (a tar or cpio by default) that could be decodeable by a
> > pax or cpio, which then reports some silly number when it attempts to
> > extract an archive size from the given garbage (a non-tar mail part).
> > 
> > If you still have such sample message, try exploding it to its parts
> > and check what a file(1) command has to say about each.
> 
> Note:
> One of them contained a dozen of PEM format X.509 certificates,
> i.e. plain text attachments.

Correction: a tar.gz archive containing several small text files.
I can reproduce the problem with this mail.

level2 logs:

Oct 21 11:42:09 host-b amavis[17160]: (17160-04) ESMTP:[::ffff:192.0.2.72]:10024 /var/lib/amavis/tmp/amavis-20111021T114209-17160: <kissg at ssg.ki.iif.hu> -> <kissg at niif.hu> SIZE=19159 BODY=8BITMIME Received: from host-s.example.com ([IPv6:::ffff:192.0.2.244]) by host-b.example.com (host-b.example.com [::ffff:192.0.2.72]) (amavisd-new, port 10024) with ESMTP for <kissg at niif.hu>; Fri, 21 Oct 2011 11:42:09 +0200 (CEST)
Oct 21 11:42:09 host-b amavis[17160]: (17160-04) Checking: 5BF8MOvZcLL8 [192.0.2.47] <kissg at ssg.ki.iif.hu> -> <kissg at niif.hu>
Oct 21 11:42:09 host-b amavis[17160]: (17160-04) Open relay? Nonlocal recips but not originating: kissg at niif.hu
Oct 21 11:42:09 host-b amavis[17160]: (17160-04) p003 1 Content-Type: multipart/mixed
Oct 21 11:42:09 host-b amavis[17160]: (17160-04) p001 1/1 Content-Type: text/plain, size: 498 B, name: 
Oct 21 11:42:09 host-b amavis[17160]: (17160-04) p002 1/2 Content-Type: application/octet-stream, size: 10680 B, name: 20111018-CSRs.tar.gz
Oct 21 11:42:09 host-b amavis[17160]: (17160-04) (!)Exceeded storage quota 9579500 bytes by do_pax_cpio/pre; last chunk 68719493333 bytes
Oct 21 11:42:09 host-b amavis[17160]: (17160-04) Decoding of p004 (POSIX tar archive (GNU)) failed, leaving it unpacked: Exceeded storage quota 9579500 bytes by do_pax_cpio/pre; last chunk 68719493333 bytes
Oct 21 11:42:09 host-b amavis[17160]: (17160-04) NOTICE: Virus scanning skipped: Exceeded storage quota 9579500 bytes by do_pax_cpio/pre; last chunk 68719493333 bytes
Oct 21 11:42:12 host-b amavis[17160]: (17160-04) (!)NOTICE: HOLD reason: Exceeded storage quota 9579500 bytes by do_pax_cpio/pre; last chunk 68719493333 bytes
Oct 21 11:42:12 host-b amavis[17160]: (17160-04) (!)Inserting header field: X-Amavis-Hold: Exceeded storage quota 9579500 bytes by do_pax_cpio/pre; last chunk 68719493333 bytes
Oct 21 11:42:12 host-b amavis[17160]: (17160-04) FWD via SMTP: <kissg at ssg.ki.iif.hu> -> <kissg at niif.hu>,BODY=7BIT 250 2.0.0 Ok, id=17160-04, from MTA([::ffff:192.0.2.244]:10025): 250 2.0.0 Ok: queued as 5C6E215F
Oct 21 11:42:12 host-b amavis[17160]: (17160-04) Passed UNCHECKED, MTA=[::ffff:192.0.2.244], [192.0.2.47] [192.0.2.47] <kissg at ssg.ki.iif.hu> -> <kissg at niif.hu>, Message-ID: <msgid1 at example.com>, Resent-Message-ID: <msgid2 at example.com>, mail_id: 5BF8MOvZcLL8, Hits: -1.9, size: 19159, queued_as: 5C6E215F, 2808 ms
Oct 21 11:42:12 host-b amavis[17160]: (17160-04) TIMING-SA total 2539 ms - parse: 5 (0.2%), extract_message_metadata: 17 (0.7%), get_uri_detail_list: 4 (0.1%), tests_pri_-1000: 21 (0.8%), tests_pri_-950: 1.53 (0.1%), tests_pri_-900: 1.61 (0.1%), tests_pri_-400: 159 (6.2%), check_bayes: 145 (5.7%), tests_pri_0: 2024 (79.7%), check_dkim_signature: 3 (0.1%), check_dkim_adsp: 5 (0.2%), check_spf: 10 (0.4%), poll_dns_idle: 0.13 (0.0%), check_razor2: 1840 (72.5%), check_pyzor: 88 (3.5%), tests_pri_500: 3 (0.1%), tests_pri_900: 3 (0.1%), learn: 277 (10.9%), get_report: 1.70 (0.1%)
Oct 21 11:42:12 host-b amavis[17160]: (17160-04) TIMING [total 2813 ms] - SMTP greeting: 1 (0%)0, SMTP EHLO: 1 (0%)0, SMTP pre-MAIL: 1 (0%)0, mkdir tempdir: 0 (0%)0, create email.txt: 0 (0%)0, SMTP pre-DATA-flush: 3 (0%)0, SMTP DATA: 42 (2%)2, check_init: 1 (0%)2, digest_hdr: 1 (0%)2, digest_body: 0 (0%)2, gen_mail_id: 2 (0%)2, mkdir parts: 2 (0%)2, mime_decode: 19 (1%)3, get-file-type2: 14 (0%)3, decompose_part: 8 (0%)3, get-file-type1: 10 (0%)4, decompose_part: 65 (2%)6, parts_decode: 0 (0%)6, check_header: 3 (0%)6, spam-wb-list: 3 (0%)6, SA parse: 7 (0%)7, SA check: 2530 (90%)97, update_cache: 8 (0%)97, decide_mail_destiny: 1 (0%)97, fwd-connect: 20 (1%)98, fwd-xforward: 1 (0%)98, fwd-mail-pip: 2 (0%)98, fwd-rcpt-pip: 0 (0%)98, fwd-data-chkpnt: 0 (0%)98, write-header: 2 (0%)98, fwd-data-contents: 1 (0%)98, fwd-end-chkpnt: 47 (2%)99, prepare-dsn: 1 (0%)99, main_log_entry: 10 (0%)100, update_snmp: 3 (0%)100, SMTP pre-response: 0 (0%)100, SMTP response: 0 (0%)100, unlink-2-fi
 les: 0 (0%)100, rundown: ...
Oct 21 11:42:12 host-b amavis[17160]: (17160-04) ...1 (0%)100


According to logs amavisd calls /usr/bin/pax to extract archives.
Some debugging shows that pax is called a single "-v" option   :-o
and archive file is fed to stdin.

Reproducing these circumstances manually I get this:

/tmp$ gzip -c 20111018-CSRs.tar.gz | pax -v
pax: Cannot identify format. Searching...
pax: End of archive volume 1 reached
pax: unknown format, 4294978020 bytes skipped.

ATTENTION! pax archive volume change required.
Ready for archive volume: 1
Input archive name or "." to quit pax.
Archive name > Quitting pax!            <---- Ctrl-D pressed here
pax: Sorry, unable to determine archive format.
/tmp$ 


Command 'file' shows nothing strange for (un)compressed
.tar and its members.

20111018-CSRs.tar.gz:                 gzip compressed data, from Unix, last modified: Tue Oct 18 13:32:44 2011
20111018-CSRs.tar:                    POSIX tar archive (GNU)
2011oct17/ldap.20111017/ldap_csr.pem: PEM certificate request

I have no idea how to continue.... :-(

Gabor
-- 
Wenn ist das Nunstück git und Slotermeyer?
Ja! ... Beiherhund das Oder die Flipperwaldt gersput.