Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Incorrect totals for HTTP and Mail traffic #1119

Open
sorinpohontu opened this issue Mar 24, 2023 · 17 comments
Open

Incorrect totals for HTTP and Mail traffic #1119

sorinpohontu opened this issue Mar 24, 2023 · 17 comments

Comments

@sorinpohontu
Copy link
Contributor

sorinpohontu commented Mar 24, 2023

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
Froxlor Dashboard

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

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

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
Copy link
Member

d00p commented Mar 24, 2023

your goaccess report clearly states: 19.3. - 24.3.

@sorinpohontu
Copy link
Contributor Author

Sure, but Froxlor report is for This month

@sorinpohontu
Copy link
Contributor Author

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
Copy link
Member

d00p commented Mar 24, 2023

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
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Member

d00p commented Mar 27, 2023

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
Copy link
Contributor Author

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
Copy link
Member

d00p commented Mar 27, 2023

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
Copy link
Contributor Author

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
Copy link
Member

d00p commented Mar 27, 2023

no, it resolves to "Mar/2023"

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

month . / . year = Mar/2023

@sorinpohontu
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Member

d00p commented Mar 27, 2023

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

@sorinpohontu
Copy link
Contributor Author

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
Copy link
Member

d00p commented Mar 27, 2023

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
Copy link
Contributor Author

sorinpohontu commented Mar 27, 2023

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

d00p added a commit that referenced this issue Mar 27, 2023
Signed-off-by: Michael Kaufmann <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants