933352 - Time stamp is incorrect in certain email filter logs

Status: RESOLVED DUPLICATE of bug 935934

(Thunderbird :: Filters, defect)

Description

[Dan Pernokis]

User Agent: Mozilla/5.0 (Windows NT 6.1; rv:25.0) Gecko/20100101 Firefox/25.0 (Beta/Release)
Build ID: 20131025151332

Steps to reproduce:

Create a filter.  Set the action to MOVE email to a specific folder.  (For comparison, tag the email before the move.)  Also try a filter to DELETE FROM POP3, then DELETE.

Some of my filters match specific senders, some simply match all messages to the account.

FYI, I'm running TB 24.1.0 (or the most recent public release at the time), but this problem has happened since the earth cooled.


Actual results:

Filters are set to move all or selected messages on a given account to a specified folder.  The move occurs, but the time stamps in the log are always 7 pm on Dec 31, 1969!  (If tagging occurs first, the tagging is timestamped correctly, but the move still says Dec/69.)  ...AND the sender's address is not captured even though it is usually present.  Similarly, if deleting, a delete at the POP3 server is correctly stamped, but the local DELETE (ie- move to Trash) is Dec/69.

CASE 1:  Move (only)
"Applied filter "-move all-" to message from - at 31/12/1969 7:00:00 PM moved message id = to mailbox://nobody@Local%20Folders/Inbox/SPAM"

CASE 2:  Tag, then Move
"Applied filter "ESA-01 - Tag & Move" to message from ESA <[e-mail]> - Clarification (English Version) at 30/10/2013 10:46:17 AM tagged"
"Applied filter "ESA-01 - Tag & Move" to message from - at 31/12/1969 7:00:00 PM moved message id = to mailbox://nobody@Local%20Folders/Inbox/EMITS"

CASE 3:  Deletes
"Applied filter "-delete-" to message from Dead Guy <[e-mail]> - delete check at 31/10/2013 1:38:44 PM deleted from POP3 server"
"Applied filter "-delete-" to message from - at 31/12/1969 7:00:00 PM deleted "



Expected results:

I expect the time-stamp on the MOVE log to be similar to the adjacent TAG operation, since the logger obviously knows the info.

CASE 1:  Move (only)
"Applied filter "-move all-" to message from Joe Spammer <[e-mail]> at 31/10/2013 1:23:45 PM moved message id = to mailbox://nobody@Local%20Folders/Inbox/SPAM"

CASE 2:  Tag, then Move
"Applied filter "ESA-01 - Tag & Move" to message from ESA <[e-mail]> - Clarification (English Version) at 30/10/2013 10:46:17 AM tagged"
"Applied filter "ESA-01 - Tag & Move" to message from ESA <[e-mail]> - Clarification (English Version) at 30/10/2013 10:46:17 AM to mailbox://nobody@Local%20Folders/Inbox/EMITS"

CASE 3:  Deletes
"Applied filter "-delete-" to message from Dead Guy <[e-mail]> - delete check at 31/10/2013 1:38:44 PM deleted from POP3 server"
"Applied filter "-delete-" to message from Dead Guy <[e-mail]> - delete check at 31/10/2013 1:38:44 PM deleted"

Comment 1

[Wayne Mery (:wsmwk)]

sounds like bug 762318

Comment 2

[:aceman]

Can you try setting the filter to run "after classification" (in the filter properties). Does it make any difference?

Comment 3

[Dan Pernokis]

(In reply to Wayne Mery (:wsmwk) from comment #1)
> sounds like bug 762318
Yes, Wayne, it does.  Please go ahead and deal with this bug accordingly.  The only difference is that I'm sure the problem predates the 2012 dates indicated, but my logs to prove it are long gone.  Now running FF 31.0 and problem persists.

FYI, all affected mailboxes are pop3, with deletes up to a month or two later.  My one IMAP account rarely has traffic and only ADDS A STAR to the message (no DELETEs or MOVEs), so the date stamps are correct.


(In reply to :aceman from comment #2)
> Can you try setting the filter to run "after classification" (in the filter
> properties). Does it make any difference?
Ace, I tried to change several filters -- from MATCH ALL FOLLOWING to MATCH ANY FOLLOWING to MATCH ALL MESSAGES.  In every case, the drop-down choice for "after classification" is greyed out and cannot be selected, even after unchecking and rechecking the various boxes.  I also tried to create new filters, and no luck either -- cannot select "after".

Perhaps this is a new bug?  I'm running FF 31.0 and can't say how long the choice has been limited because I don't usually consider the "after" option.  I know from curiosity that it did work at one time, but I haven't actually tried it in a long while.

Comment 4

[:aceman]

(In reply to Dan Pernokis from comment #3)
> (In reply to :aceman from comment #2)
> > Can you try setting the filter to run "after classification" (in the filter
> > properties). Does it make any difference?
> Ace, I tried to change several filters -- from MATCH ALL FOLLOWING to MATCH
> ANY FOLLOWING to MATCH ALL MESSAGES.  In every case, the drop-down choice
> for "after classification" is greyed out and cannot be selected, even after
> unchecking and rechecking the various boxes.  I also tried to create new
> filters, and no luck either -- cannot select "after".
The "after classification" option does not depend on any of those "match" options.
It is enabled when you tick "getting new mail" before the dropdown.
Or do you only use the "manual run" of the filters?

> Perhaps this is a new bug?  I'm running FF 31.0 and can't say how long the
> choice has been limited because I don't usually consider the "after" option.
> I know from curiosity that it did work at one time, but I haven't actually
> tried it in a long while.
If you can show a screenshot of the "before/after classification" dropdown being disabled when "getting new mail" is selected, then that would be a new bug.

Comment 5

[:aceman]

Also, is there a difference if you use Copy instead of Move? Is the log right in that case?

Comment 6

[Dan Pernokis]

@aceman re: comment #4:
First let me clarify.  I didn't change the matches FROM something to another option.  I was trying to change the CLASSIFICATION (before/after) based on the entire range of match possibilities.  All items are used for "getting new mail" and I never configure or use any of them for manual.

For several filters on several inbox accounts, NONE of them would let me change the BEFORE/AFTER classification.  The AFTER choice is always greyed out.  If "getting new mail" is unchecked, the dropbox is irrelevant and doesn't activate at all (correct).

But I have since found that for the LOCAL INBOXES folder -- and it seems to be only for Local Folders -- the classification dropdown does work fine.  (Uncheck the box and it correctly gets deactivated, then reactivates OK again when rechecked.)

So just for semantics:  
>>> If you can show a screenshot of the "before/after classification" dropdown being disabled when 
>>> "getting new mail" is selected, then that would be a new bug.

(i) The dropdown is not disabled when checked, it just allows the one choice ("before"), for all accounts except Local Inboxes.
(ii) The dropdown is correctly disabled (does not function at all) when unchecked.
(iii) The dropdown works correctly under all conditions for the Local Folders only.


Re: Comment #5:
I have activated one of the commonly used failing filters to check COPY.
(i) PUT STAR -- as reference, this always correctly stamps with date/time and user info.
(ii) COPY to "Test-Before" -- for your benefit to see if it works (should have info)
(iii) MOVE as usual -- and this always fails (date 1969 and no user info).
(iv) COPY to "Test-After" -- again for your benefit to see if it works (might lose info on move)
(v) STOP EXECUTION -- as usual for this filter -- not present on most that fail.

I'll let you know in a day or two what happens.

Comment 7

[Dan Pernokis]

@aceman re: Followup on Comment #5 and Comment #6):

See setup in Comment #6:  I did PUT-STARs to see info (I know this works), COPY (before for ref), MOVE (the test!), and COPY (after for ref).  But TB re-ordered that to PUT, COPY, COPY, MOVE.

I chose a filter which has limited random but predictable incoming emails, on an account that also has spam filtering.  I had deliberately left a few old entries in the log for reference.  I can clearly see three distinct operations:  MOVEs and DELETEs both fail to capture timestamp and user info, while TAG & MOVE (consecutive) capture both OK for TAGs but fail on the MOVEs.

Well, surprise, surprise!  Not only did PUT-STAR capture the info, but all COPYs and MOVEs also had all the correct info too!  (Strange...  MOVE after TAG does not capture info, yet MOVE after PUT-STAR does.)

I went into some other accounts with spam filters (usually deletions) and noticed two things:  DELETE does not capture time & user (consistent with above), but DELETE FROM POP3 *does* capture both OK.  So I have added PUT-STARs to a few with regular spam and I'll let you know in a day whether the DELETEs now have info.

Comment 8

[:aceman]

This seems to be in line with the analysis in bug 935934.
Whether the info in the log is correct depends on whether the original message is still in the original receiving folder. After a MOVE/DELETE it is no longer there. But after a COPY or DELETE ON SERVER a copy of it is still there.

Comment 9

[Dan Pernokis]

I've posted the following to Bug 762318 and Bug 935934 as a workaround:

"MOVE and DELETE do not capture timestamp and user info in the log (date is 31 Dec 1969).  (DELETE is basically a MOVE to Trash.)  But if you do a PUT-STAR prior to the MOVE or DELETE, then it not only captures time & info for the PUT-STAR but now also has it for the MOVE or DELETE.

But strangely, although TAG will also capture time & info, its subsequent MOVE or DELETE does not.

I also noticed that DELETE FROM POP3 also captures the time & info, although a corresponding DELETE does not."

Comment 10

[WADA:World Anti-bad-Duping Agency]

> Bug summary : Time stamp is incorrect in certain email filter logs 

Does "incorrect timestamp in your case" involve "timestmp other than EPOC time"? Or EPOC time only?
If EPOC time only, dup of bug 762318.

(In reply to Dan Pernokis from comment #9)
> "MOVE and DELETE do not capture timestamp and user info in the log (date is 31 Dec 1969).

Action=Stop Filter  Execution, Action=Delete, Action=Move, are action of same category : Final action  on a mail.
So, "timing of filter log is written" is same.
Because  "timing of filter log is written" is same, bug 762318 should occurs on Action=Stop Filter  Execution and Action=Delete too.
However, as known by bug 537501, bug 552936, bug 695671 etc., Action=Delete and Action=Stop Filter Execution has severe problem(fixed in nightly/beta only).
Please avoid referring to Action=Delete in bug 762318. Action=Move case is sufficient for problem analysis and resolving problem.
Please refer to Action=Stop Filter  Execution, Action=Delete only when you report "fix verification test result" to that bug.

Comment 11

[WADA:World Anti-bad-Duping Agency]

And, problem is already fixed by bug 935934...