Delivery delay problems

From: Marco TCHI HONG (no email)
Date: Fri Sep 26 2008 - 03:49:23 EDT

  • Next message: Alan Boyd: "Rejecting email to unknown users at a virtual domain"

    Hello,
    I am using Postfix 2.3.3 and Kaspersky Antispam/Antivirus on our MX.
    Mailboxes are hosted on another server.
    The MX is relaying 250 domains or so, and it doesn't have resources
    issues.

    Our problem is that mail stay a long time in the active queue before the
    content filter, but when it's sent to the server where mailboxes are
    stored there's no problem:

    Sep 26 10:11:57 mx postfix/smtp[1387]: 1906C718411:
    to=<>, relay=127.0.0.1[127.0.0.1]:9026, conn_use=5,
    delay=230, delays=0.93/210/0/19, dsn=2.0.0, status=sent (250 2.0.0 Ok
    (2.0.0 Ok: queued as 5A0B6718ACF ))

    Sep 26 10:11:57 mx postfix/smtp[744]: 5A0B6718ACF:
    to=<>, relay=zsmtp.dts.mg[196.192.32.54]:25,
    delay=0.12, delays=0.08/0.01/0/0.03, dsn=2.0.0, status=sent (250 2.0.0 Ok:
    queued as 6D55BF70AA2)

    So I went debug mode for the queue manager, and I don't see any
    errors...but it takes 3 minutes and 30 seconds (see logs below) before the
    mail is sent to the content filter. What could be the cause?

    Sep 26 10:08:08 mx postfix/qmgr[669]: qmgr_active_feed: queue incoming
    Sep 26 10:08:08 mx postfix/qmgr[669]: qmgr_active_feed:
    incoming/1906C718411
    Sep 26 10:08:08 mx postfix/qmgr[669]: qmgr_message_alloc: active
    1906C718411
    Sep 26 10:08:08 mx postfix/qmgr[669]: record C 529
    565 1
             0
    Sep 26 10:08:08 mx postfix/qmgr[669]: record T 1222412887 94462
    Sep 26 10:08:08 mx postfix/qmgr[669]: record A create_time=1222412887
    Sep 26 10:08:08 mx postfix/qmgr[669]: record L kas3scan:127.0.0.1:9026
    Sep 26 10:08:08 mx postfix/qmgr[669]: record A rewrite_context=remote
    Sep 26 10:08:08 mx postfix/qmgr[669]: record S
    Sep 26 10:08:08 mx postfix/qmgr[669]: 1906C718411:
    from=<>, size=529, nrcpt=1 (queu
    e active)
    Sep 26 10:08:08 mx postfix/qmgr[669]: record A log_client_name=dts.dts.mg
    Sep 26 10:08:08 mx postfix/qmgr[669]: record A
    log_client_address=193.251.140.178
    Sep 26 10:08:08 mx postfix/qmgr[669]: record A
    log_message_origin=dts.dts.mg[193.251.140.178]
    Sep 26 10:08:08 mx postfix/qmgr[669]: record A log_helo_name=[127.0.0.1]
    Sep 26 10:08:08 mx postfix/qmgr[669]: record A log_protocol_name=ESMTP
    Sep 26 10:08:08 mx postfix/qmgr[669]: record A client_name=dts.dts.mg
    Sep 26 10:08:08 mx postfix/qmgr[669]: record A
    reverse_client_name=dts.dts.mg
    Sep 26 10:08:08 mx postfix/qmgr[669]: record A
    client_address=193.251.140.178
    Sep 26 10:08:08 mx postfix/qmgr[669]: record A helo_name=[127.0.0.1]
    Sep 26 10:08:08 mx postfix/qmgr[669]: record A client_address_type=2
    Sep 26 10:08:08 mx postfix/qmgr[669]: record A
    dsn_orig_rcpt=rfc822;
    Sep 26 10:08:08 mx postfix/qmgr[669]: record O
    Sep 26 10:08:08 mx postfix/qmgr[669]: record R
    Sep 26 10:08:08 mx postfix/qmgr[669]: record M
    Sep 26 10:08:08 mx postfix/qmgr[669]: record X
    Sep 26 10:08:08 mx postfix/qmgr[669]: record E
    Sep 26 10:08:08 mx postfix/qmgr[669]: dir_forest: 1906C718411 -> 1/
    Sep 26 10:08:08 mx postfix/qmgr[669]: start sorted recipient list
    Sep 26 10:08:08 mx postfix/qmgr[669]: qmgr_message_sort:

    Sep 26 10:08:08 mx postfix/qmgr[669]: end sorted recipient list
    Sep 26 10:08:08 mx postfix/qmgr[669]: start sorted recipient list
    Sep 26 10:08:08 mx postfix/qmgr[669]: qmgr_message_sort:

    Sep 26 10:08:08 mx postfix/qmgr[669]: end sorted recipient list
    Sep 26 10:08:08 mx postfix/qmgr[669]: watchdog_start: 0x9594160

    Sep 26 10:11:38 mx postfix/qmgr[669]: qmgr_active_feed: queue incoming
    Sep 26 10:11:38 mx postfix/qmgr[669]: transport_event: kas3scan
    Sep 26 10:11:38 mx postfix/qmgr[669]: private/kas3scan socket: wanted
    attribute: status
    Sep 26 10:11:38 mx postfix/qmgr[669]: input attribute name: status
    Sep 26 10:11:38 mx postfix/qmgr[669]: input attribute value: 0
    Sep 26 10:11:38 mx postfix/qmgr[669]: private/kas3scan socket: wanted
    attribute: (list terminator)
    Sep 26 10:11:38 mx postfix/qmgr[669]: input attribute name: (end)
    Sep 26 10:11:38 mx postfix/qmgr[669]: qmgr_peer_select: 1906C718411
    kas3scan 127.0.0.1:9026 (80 of 8
    0)
    Sep 26 10:11:38 mx postfix/qmgr[669]: qmgr_job_retire: 1906C718411
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr flags = 2051
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr queue_name = active
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr queue_id = 1906C718411
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr offset = 565
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr size = 529
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr nexthop = 127.0.0.1:9026
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr encoding =
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr sender =
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr envelope_id =
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr ret_flags = 0
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr time = [data 44 bytes]
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr log_client_name =
    dts.dts.mg
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr log_client_address =
    193.251.140.178
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr log_protocol_name = ESMTP
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr log_helo_name =
    [127.0.0.1]
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr sasl_method =
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr sasl_username =
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr sasl_sender =
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr rewrite_context = remote
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr recipient_count = 1
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr original_recipient =

    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr recipient =

    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr offset = 540
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr dsn_orig_rcpt =
    rfc822;
    Sep 26 10:11:38 mx postfix/qmgr[669]: send attr notify_flags = 0
    Sep 26 10:11:38 mx postfix/qmgr[669]: qmgr_deliver: site `127.0.0.1:9026'
    Sep 26 10:11:38 mx postfix/qmgr[669]: watchdog_start: 0x9594160

    Sep 26 10:11:57 mx postfix/qmgr[669]: qmgr_active_done: 1906C718411
    Sep 26 10:11:57 mx postfix/qmgr[669]: 1906C718411: removed
    Sep 26 10:11:57 mx postfix/qmgr[669]: qmgr_job_free: 1906C718411 kas3scan


  • Next message: Alan Boyd: "Rejecting email to unknown users at a virtual domain"





    Hosted Email Solutions

    Invaluement Anti-Spam DNSBLs



    Powered By FreeBSD   Powered By FreeBSD