mailinabox usage report truncated over year change

[pencotts]

My usage report for 4thJan2021 contained only

Scanning logs from 2020-12-28 03:28:02 to 2021-01-04 03:28:02
2 Log lines scanned, 0 lines parsed in 0.09 seconds

I believe the change made for 1733 in _management/mail_log.py_ substitutes the wrong year: on the year rollover the date from the log will have the current year applied to a date which may be in the previous year (in my case in december 2020), so the check:

if date > START_DATE:

will succeed stopping processing.

# date = datetime.datetime.strptime(date, '%b %d %H:%M:%S')                                                                                                                                       
# date = date.replace(START_DATE.year)                                                                                                                                                            

# strptime fails on Feb 29 if correct year is not provided. See https://bugs.python.org/issue26460                                                                                                
date = datetime.datetime.strptime(str(START_DATE.year) + ' ' + date, '%Y %b %d %H:%M:%S')
# print("date:", date)                                                                                                                                                                            

# Check if the found date is within the time span we are scanning                                                                                                                                 
# END_DATE < START_DATE                                                                                                                                                                           
if date > START_DATE:
    # Don't process, and halt                                                                                                                                                                     
    return False

[plittlefield]

Yes, happening for me too.

[myfirstnameispaul]

@pencotts

Can you submit a PR?

[hija]

Are we sure miab is able to recover from this bug? This bug reports talks about the change over the year, but in a forum someone mentions a timespan which is not from 2020-2021: https://discourse.mailinabox.email/t/empty-usage-report/7499

[myfirstnameispaul]

What is the actual dates the user reports the error on? I see only mention of 2021-01-04.

My reports are not truncated through 2020-12-28.

[drpixie]

I'm the person who made the discourse report https://discourse.mailinabox.email/t/empty-usage-report/7499

My last good report was "Scanning logs from 2020-12-21 03:01:01 to 2020-12-28 03:01:01" send on 2020-12-28.
The first bad report was "Scanning logs from 2020-12-28 03:01:01 to 2021-01-04 03:01:01" send on 2021-01-04

So this is probably the same bug ... just the timing of my update to 0.51 adds a confusing factor!

[cmasterdelphi]

Same issue:
Last good one: Scanning logs from 2020-12-21 03:33:01 to 2020-12-28 03:33:01
First bad one: Scanning logs from 2020-12-28 03:33:02 to 2021-01-04 03:33:02
Second bad one: Scanning logs from 2021-01-04 03:33:01 to 2021-01-11 03:33:01

MiaB Version: 0.51
Last Reboot: 8th January 2021

[plittlefield]

Yep, me too...

/root/mailinabox/management/mail_log.py -t week 
Scanning logs from 2021-01-04 11:34:07 to 2021-01-11 11:34:07
2 Log lines scanned, 0 lines parsed in 0.09 seconds

...which logs does it scan... presumably /var/log/mail.log?

-rw-r----- 1 syslog adm 34K 2021-01-11 11:19 /var/log/mail.log`

$ wc -l /var/log/mail.log
238 /var/log/mail.log

Thanks,

Paully

[hija]

+1. So this Error does not only occur during the year change and it continues. Anyone interested in debugging and making a PR for this?

[iceaway]

I had a quick look, and it seems like the timestamps in the log files do not have the year in them. So when it compares dates to determine if the log files has anything relevant in them, it assumes that the year is the current year unless you specify it manually with the -d flag. I can get valid logs by doing i.e.:

./mail_log.py -d 2020-12-15 -t week

[plittlefield]

Ah yes, I get something now - but I have another problem...

./mail_log.py -d 2020-12-15 -t week
Setting start date to 2020-12-15 00:00:00
Scanning logs from 2020-12-08 00:00:00 to 2020-12-15 00:00:00
717 Log lines scanned, 306 lines parsed in 0.06 seconds

Sent email
Traceback (most recent call last):
  File "./mail_log.py", line 874, in <module>
    scan_mail_log(env_vars)
  File "./mail_log.py", line 143, in scan_mail_log
    print_header(msg)
  File "./mail_log.py", line 791, in print_header
    print("\u2550" * len(msg), '\n')
UnicodeEncodeError: 'ascii' codec can't encode characters in position 0-9: ordinal not in range(128)

:-)

Paully

[hija]

@plittlefield I think that's ok, because the daemon calls the script with UTF-8 support. So the ASCII Error should not occur!

[plittlefield]

I have fixed the python error by adding some more locales to the system...

$ sudo dpkg-reconfigure locales

$ locale -a
C
C.UTF-8
en_GB.utf8
en_US.utf8
POSIX

...so when I run with the -d date option it works.

...but the output is blank if I leave out the -d option.

Regards,

Paully

[myfirstnameispaul]

It looks like one of the forum users is reporting that when running on 2020-01-04 on MiaB .48 the messages are still truncated:

https://discourse.mailinabox.email/t/empty-usage-report/7499/4

I'm guessing this is from PR https://github.com/mail-in-a-box/mailinabox/pull/1734?

[hija]

Okay, so here's my understanding of the bug:

1. We define a timeframe (day/month/year to day/month/year) for the usage report. All information in this timeframe shall be reported. In this example, let's use the first week of january, e.g. 1/1/2021-08/01/2021.
2. The logfiles are processed from the oldest to the newst logfile. This means, your oldest logfile, e.g. from December, are processed first.
3. The logfiles themselves only contain the day and the month, but not the year. Because we start with the oldest logfile, our month is december and because we do not keep track of the year in the log file, the script assumes that is has to be the current year. Thus, our "oldest" logfile seems to be from december 2021 (which is in reality - as we all know - in the future, but our script does not know that!). Because our oldest logfile is even newer than our timespan (which goes to 08/01/2021), we stop the usage report here.

As pointed out by @pencotts in the first place, the error is that we do not keep track of the year of the logfile and instead assume that the logfile must be from the current year.

Idea for a bugfix:

Instead of appending the current year (START_DATE.year), we append the year of the creation date of the logfile. This could be a suitable solution, since the year seems to be correct there:

root@box:~/mailinabox# ls -la --full-time /var/log/mail.log*
-rw-r----- 1 syslog adm 544142 2021-01-11 22:51:29.696065572 +0100 /var/log/mail.log
-rw-r----- 1 syslog adm 2682065 2021-01-11 03:11:10.806852644 +0100 /var/log/mail.log.1
-rw-r----- 1 syslog adm 119493 2021-01-04 03:11:11.000000000 +0100 /var/log/mail.log.2.gz
-rw-r----- 1 syslog adm 240791 2020-12-29 03:11:09.000000000 +0100 /var/log/mail.log.3.gz
-rw-r----- 1 syslog adm 154022 2020-12-21 03:46:11.000000000 +0100 /var/log/mail.log.4.gz

(Lazy) Bugfix in the meanwhile: Delete the logfiles from december (in my example: mail.log.4.gz and mail.log.3.gz). Otherwise wait a few more weeks until the problem disappears by itself✨

[plittlefield]

Sounds good!

[iceaway]

Nice idea @hija! Unfortunately the file creation time does not seem to be readily available on Linux system via any standard interfaces. We can read the last access, modification and metadata change timestamps, of which metadata change is probably the closest. But it does not work here as I have one log file spanning the rollover from 2020 to 2021, and the metadata change timestamp is set to 2021, so it thinks the log starts with entries from the end of december 2021.

[jeremitu]

Sorry, my fault. It came with #1733 a fix for 29.02.2020. I have an fix for mail_log.py around line 345:

    # Replaced the dateutil parser for a less clever way of parser that is roughly 4 times faster.
    # date = dateutil.parser.parse(date)
    try:
        date = datetime.datetime.strptime(date, '%b %d %H:%M:%S')
        # apply month heuristic around the end of the year
        if date.month >= 6:
          date = date.replace(END_DATE.year)
        else:
          date = date.replace(START_DATE.year)
    except ValueError:
        # strptime fails on Feb 29 with ValueError: day is out of range for month if correct year is not provided.
        # See https://bugs.python.org/issue26460
        date = datetime.datetime.strptime(str(START_DATE.year) + ' ' + date, '%Y %b %d %H:%M:%S')
    #print("date:", date)

Ugly, but works. Please test, I will provide a PR.

[iceaway]

Sorry, my fault. It came with #1733 a fix for 29.02.2020. I have an fix for mail_log.py around line 345:

    # Replaced the dateutil parser for a less clever way of parser that is roughly 4 times faster.
    # date = dateutil.parser.parse(date)
    try:
        date = datetime.datetime.strptime(date, '%b %d %H:%M:%S')
        # apply month heuristic around the end of the year
        if date.month >= 6:
          date = date.replace(END_DATE.year)
        else:
          date = date.replace(START_DATE.year)
    except ValueError:
        # strptime fails on Feb 29 with ValueError: day is out of range for month if correct year is not provided.
        # See https://bugs.python.org/issue26460
        date = datetime.datetime.strptime(str(START_DATE.year) + ' ' + date, '%Y %b %d %H:%M:%S')
    #print("date:", date)

Ugly, but works. Please test, I will provide a PR.

This does not work for me unfortunately. No time to debug yet, will try to look it later.

[hija]

Another heuristics idea:

If the calculated date of the logfile > today() then replace the year with the previous one?