mail in queue not shown as deferred

[dazoot]

We have some mails in the queue which seem to be hanged.

Message looks like:

{
    "messages": [
        {
            "id": "1636695418700056aa",
            "recipient": "test@example.com",
            "seq": "001",
            "status": "QUEUED",
            "zone": "zone1"
        }
    ],

In the log if i search for that message id, i see it has been tried a couple of times but deferred count is not incremented and staus remains QUEUED.

Zonemta log (removed the sensitive part):

May 16 06:41:21 server zone-mta: info Sender/zone1/5128[1] 1636695418700056aa.001 CONNECTING 
May 16 06:41:21 server zone-mta: info Sender/zone1/5128[1] 1636695418700056aa.001 CONNECTED 
May 16 06:41:22 server zone-mta: info Sender/zone1/5128[1] 1636695418700056aa.001 DEFERRED[defer] 
May 16 06:41:22 server zone-mta: info Sender/zone1/5128[1] 1636695418700056aa.001 SMTPCLOSE [3awFlqUVXK4] Connection closed response="550 5.7.606 
May 16 10:13:00 server zone-mta: info Sender/zone1/5117[4] 1636695418700056aa.001 CONNECTING 
May 16 10:13:00 server zone-mta: info Sender/zone1/5117[4] 1636695418700056aa.001 CONNECTED 
May 16 10:13:01 server zone-mta: info Sender/zone1/5117[4] 1636695418700056aa.001 DEFERRED[defer] 
May 16 10:13:01 server zone-mta: info Sender/zone1/5117[4] 1636695418700056aa.001 SMTPCLOSE [yyQcSKcGbqU] Connection closed response="550 5.7.606 

[andris9]

How does the message entry in db looks like?

db['zone-queue'].findOne({id: '1636695418700056aa', seq: '001'})

[dazoot]

I have deleted the old queue but here is an example for another id:

{
        "_id" : ObjectId("5afb8a560e325a1398ed749e"),
        "id" : "163669461cf00056aa",
        "seq" : "001",
        "domain" : "example.com",
        "sendingZone" : "test1
        "recipient" : "test@example.com"
        "locked" : false,
        "lockTime" : 1526456032476,
        "assigned" : "default",
        "queued" : ISODate("2018-05-16T07:38:53.619Z"),
        "created" : ISODate("2018-05-16T01:33:10.555Z"),
        "_deferred" : {
                "first" : 1526456033619,
                "count" : 1,
                "last" : 1526456033619,
                "next" : 1526456333619,
                "response" : "550 Please resolve this and retry.",
                "log" : [
                        {
                                "time" : 1526456032605,
                                "level" : "INF",
                                "tnx" : "network",
                                "message" : "Connection established to :25"
                        },

Deferred count = 1.

[dazoot]

I think the bug is in the mail-queue getInfo method.

let deferred = delivery.queued > curtime;

Can this be because curtime is in localtimezone and mongo date is stored in UTC ?

[andris9]

The comparison is a bit off, it seems to be comparing date object against timestamp number but it should work correctly though as the date object is cast into a number for the comparison. Both values are UTC.

"queued" time indicates the time when ZoneMTA is allowed to make a delivery attempt, If the queue time is in the future then the resulting status is DEFERRED, otherwise it is QUEUED (so the status has nothing to do if the message was actually deferred or not). If the message queue time is already past but the message is not fetched from the queue for whatever reason, then you get QUEUED. If your message is in a QUEUED state for a long time then it means there's something wrong with the queueing system, maybe some data hasn't been cleared up or so. You may try to restart the zone-mta service which should clear any intermediate state.

[dazoot]

So the problem is that the http API method does not return the message as deferred even though it has deferred count stored in Mongo. Restart does not fix it.

[dazoot]

I did some debug and i get this:

log.verbose("getInfo", "getInfo queued %s curtime %s, deferred = %s", delivery.queued, curtime, deferred);

May 17 12:41:06 server zone-mta: verb getInfo getInfo queued Thu May 17 2018 08:11:32 GMT+0300 (EEST) curtime 1526550066523, deferred = false

[andris9]

Deferred count is unimportant in this case. API responds the status as DEFERRED for messages that should be delivered in the future ("queued" time is in the future) and QUEUED for messages that should be delivered in the first possible occasion ("queued" time is now or in the past). The real question is that if the message should be delivered immeditatelly, why is it in the queue for so long.

[dazoot]

This happens just on very slow machines with msgs in the queue.

Chaning this fixes the API method:

                        // let deferred = delivery.queued > curtime;
                        let deferred = delivery._deferred || false;

[dazoot]

I will close this since it's just API related and has nothing to do with the actual queue.