Incorrect totals for HTTP and Mail traffic

[sorinpohontu]

Describe the bug
Traffic reports totals are 0 (for Main) and/or different than goaccess totals (HTTP).

Froxlor shows for this month (today is 24/Mar/2023): Total 835.20 MB, 748.18 MB HTTP, 87.02 MB FTP, 0.00 B Mail

GoAccess reports for 24/Mar/2023 — 24/Mar/2023 : Tx. Amount 2.44 GiB

Dashboard reports crons:
Traffic calculation: 23.03.2023 22:00
Web- and traffic-reports: 23.03.2023 22:05

Weird as there was traffic on HTTP and Mail (IMAP), see attached screens.

System information

• Froxlor version: 2.0.13
• Web server: apache2
• DNS server: none
• POP/IMAP server: Dovecot
• SMTP server: postfix
• FTP server: proftpd
• OS/Version: Debian 11

To Reproduce
Steps to reproduce the behavior:
See attached screens

Expected behavior
Updated traffic reports.

Logfiles
/var/log/mail.log

2023-03-21T08:35:27.801789+02:00 system dovecot: imap([email protected])<55712><JZyuPmP3hvJWIoLW>: Connection closed (SELECT finished 16.138 secs ago) in=836 out=3593

Additional context
There are no changes to default logs format, logs are rotated once a day.

Debian Bullseye (11.x) » Mailserver (IMAP/POP3) » Dovecot with postfix
/etc/dovecot/conf.d/20-imap.conf: imap_logout_format is not changed (default)
/etc/dovecot/conf.d/20-managesieve.conf: managesieve_logout_format is not changed (default)
/etc/dovecot/conf.d/20-pop3.conf: pop3_logout_format = in=%i out=%o top=%t/%p, retr=%r/%b, del=%d/%m, size=%s

[d00p]

your goaccess report clearly states: 19.3. - 24.3.

[sorinpohontu]

Sure, but Froxlor report is for This month

[sorinpohontu]

I have updated mail.log.
I did test the regexp from https://github.com/Froxlor/Froxlor/blob/bf7d22a79470c974cabdcb8565f2b19104e08c49/lib/Froxlor/MailLogParser.php#L239 and it is a match to line from mail.log

[d00p]

Hm, froxlor stores the result of goaccess's json output, cant tell you for now why this does not match, this has been testen quiet a bit ...
Need to test and debug, hard to say

[sorinpohontu]

The tests are on two instances of Froxlor, with identical setups. Same issue on both servers.
Also, is weird to have all Mail traffic to 0.

[sorinpohontu]

About HTTP traffic: I did some debug and think I found the issue.

According to /etc/logrotate.d/froxlor, logs are rotated daily. On Debian 11, logrotation occurs at midnight.

/var/log/syslog

2023-03-27T00:00:01.506947+03:00 system CRON[265317]: (root) CMD (/usr/bin/nice -n 5 /usr/bin/php -q /var/www/html/froxlor/bin/froxlor-cli froxlor:cron 'traffic' -q 1> /dev/null)
2023-03-27T00:00:04.654219+03:00 system systemd[1]: Starting logrotate.service - Rotate log files...
2023-03-27T00:00:04.777819+03:00 system systemd[1]: Reloading apache2.service - The Apache HTTP Server...
2023-03-27T00:00:04.817369+03:00 system systemd[1]: Reloaded apache2.service - The Apache HTTP Server.
2023-03-27T00:00:05.790092+03:00 system systemd[1]: Reloading apache2.service - The Apache HTTP Server...
2023-03-27T00:00:05.826501+03:00 system systemd[1]: Reloaded apache2.service - The Apache HTTP Server.
2023-03-27T00:00:05.840882+03:00 system systemd[1]: logrotate.service: Deactivated successfully.
2023-03-27T00:00:05.840958+03:00 system systemd[1]: Finished logrotate.service - Rotate log files.

I did some tests, and for a log file of 98567K the processing take about about 30 seconds:

time goaccess --log-format=COMBINED -a -d /var/www/logs/client-domain.tld-access.log.1 -o report.json
Parsing... [306,438] [10,214/s]]

real	0m29.982s
user	0m2.009s
sys	0m0.462s

See https://github.com/Froxlor/Froxlor/blob/bf7d22a79470c974cabdcb8565f2b19104e08c49/lib/Froxlor/Cron/Traffic/TrafficCron.php#L633
$logfile = FileDir::makeCorrectFile(Settings::Get('system.logfiles_directory') . $logfile . '-access.log');

Are we sure the logfile is not rotated from start of cron traffic start until end ?

I think it would be better to run froxlor-cli froxlor:cron 'traffic' after logrotation and maybe process -access.log.1 instead of -access.log.

What do you think ?

[d00p]

your test is missing that we also grep "YYYY/MM" from the access log, see https://github.com/Froxlor/Froxlor/blob/bf7d22a79470c974cabdcb8565f2b19104e08c49/lib/Froxlor/Cron/Traffic/TrafficCron.php#L661

And yes, maybe it's generally a better idea to have the traffic cron run early in the morning and use the rotated .1 file

[sorinpohontu]

your test is missing that we also grep "YYYY/MM" from the access log, see

I think that would be another issue: grep-ing for YYYY/MM is not correct, since Apache2 default log format is different, at least on Debian 11. That may depend on user date and time settings.

xx.xx.xx.xx - - [27/Mar/2023:00:00:06 +0300] "GET / HTTP/1.1" 200 27783 "-" "Mozilla/5.0 (compatible; AhrefsBot/7.0; +http://ahrefs.com/robot/)"

[d00p]

it's formatted to use the short-name of month and year correctly, see https://github.com/Froxlor/Froxlor/blob/bf7d22a79470c974cabdcb8565f2b19104e08c49/lib/Froxlor/Cron/Traffic/TrafficCron.php#L189

it was just an example that we grep the current month from the log, sorry for the confusion

[sorinpohontu]

I meant Apache log date format [27/Mar/2023:00:00:06 +0300] is different than format expected by grep:

$monthyear = $monthyear_arr['month'] . '/' . $monthyear_arr['year']; => 2023/03

[d00p]

no, it resolves to "Mar/2023"

month = date('M') = 'Mar'
year = date('Y') = 2023

month . / . year = Mar/2023

[sorinpohontu]

Than maybe the cause is log being rotated and -access.log vanishes from disk ...

Processing -access.log.1 should take in consideration first day of month and first day of year ...

[sorinpohontu]

One more question about Postfix / Dovecot: if Settings::Get("system.mtalog") and Settings::Get("system.mdalog") points to same file (/var/log/mail.log), isn't this doubling Postfix traffic ?

Or maybe it's an error here: `$this->parsePostfixLog(Settings::Get("system.mdalog") . ".1");

That should be $this->parseDovecotLog(Settings::Get("system.mdalog") . ".1");

[d00p]

doesnt matter if its the same file, the regex matches are different for the two services

[sorinpohontu]

Yes, but line is if (Settings::Get("system.mdaserver") == "dovecot") {.
That means parseDovecotLog will ignore previous log Settings::Get("system.mdalog") . ".1" and will process it once again as $this->parsePostfixLog(Settings::Get("system.mdalog") . ".1");

[d00p]

you start mixing up a lot of different topics here, why no just join discord for discussion - it gets messy here and hard to follow

[sorinpohontu]

Oki doki. If needed, you can close this issue and make separate issues for HTTP and MAIL.