Graph suddenly stopped

[stefaweb]

Modoboa: 1.13.1 Modoboa-stat: 1.4.1 OS: Debian Stretch

The graph on my production serveur suddenly stopped to work.

Do we have a way to know what is happening?

[stefaweb]

Hi!

More on this.

If I manually launch : # /srv/modoboa/env/bin/python /srv/modoboa/instance/manage.py logparser, I got:

Traceback (most recent call last):
  File "/srv/modoboa/instance/manage.py", line 22, in <module>
    execute_from_command_line(sys.argv)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/__init__.py", line 364, in execute_from_command_line
    utility.execute()
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/__init__.py", line 356, in execute
    self.fetch_command(subcommand).run_from_argv(self.argv)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/base.py", line 283, in run_from_argv
    self.execute(*args, **cmd_options)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/base.py", line 330, in execute
    output = self.handle(*args, **options)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/modoboa_stats/management/commands/logparser.py", line 587, in handle
    p.process()
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/modoboa_stats/management/commands/logparser.py", line 552, in process
    for line in self.f.readlines():
  File "/srv/modoboa/env/lib/python2.7/codecs.py", line 314, in decode
    (result, consumed) = self._buffer_decode(data, self.errors, final)
UnicodeDecodeError: 'utf8' codec can't decode byte 0xe9 in position 1362: invalid continuation byte

Nothing found in various logs.

[stefaweb]

And with:

# /srv/modoboa/env/bin/python /srv/modoboa/instance/manage.py update_statistics

Traceback (most recent call last):
  File "/srv/modoboa/instance/manage.py", line 22, in <module>
    execute_from_command_line(sys.argv)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/__init__.py", line 364, in execute_from_command_line
    utility.execute()
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/__init__.py", line 356, in execute
    self.fetch_command(subcommand).run_from_argv(self.argv)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/base.py", line 283, in run_from_argv
    self.execute(*args, **cmd_options)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/base.py", line 330, in execute
    output = self.handle(*args, **options)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/modoboa_stats/management/commands/update_statistics.py", line 84, in handle
    self.update_account_creation_stats(options["rebuild"])
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/modoboa_stats/management/commands/update_statistics.py", line 79, in update_account_creation_stats
    rrdtool.update(str(db_path), *data)
rrdtool.OperationalError: /srv/modoboa/rrdfiles/new_accounts.rrd: illegal attempt to update using time 1552024800 when last update time is 1552024800 (minimum one second step)

[tonioo]

@stefaweb For the first one, it looks like you have some strange characters in the mail log file, or an issue with encoding. Can you check the file's encoding? About the second, the script is trying to update the RRD file with the same timestamp twice, which is not allowed... I need to check that.

[stefaweb]

I got this with Postfix log file:

# file -bi /var/log/mail.log
text/plain; charset=us-ascii

Postfix version:

ii  postfix                         3.1.8-0+deb9u1                 amd64        High-performance mail transport agent
ii  postfix-mysql                   3.1.8-0+deb9u1                 amd64        MySQL map support for Postfix
ii  postfix-sqlite                  3.1.8-0+deb9u1                 amd64        SQLite map support for Postfix

[tonioo]

@stefaweb Can you check if there is any message in french in the log file?

[stefaweb]

@tonioo Can you be more specific?

[tonioo]

@stefaweb Do you see non ascii content in the /var/log/mail.log file? (like words with accents, etc.)

[stefaweb]

Found this:

# grep -axv '.*' mail.log
Mar  4 15:50:30 mailhub opendkim[4663]: 9AE3EBC06C8: can't parse From: header value ' "Accueil - Les D�lices du Valplessis"'

[stefaweb]

The date of the recording in the logs seems to correspond to the stop of the recording of the graphs.

[tonioo]

@stefaweb This is the reason why the script fails... I'll try to fix it but in the meantime, you can remove this line from the file and stats should work again.

[stefaweb]

ok

[stefaweb]

Stats are back.

I still have the error message with rrdfiles using update_statistics.

[Salamek]

@tonioo My stats are not working anymore:

/srv/modoboa/env/bin/python /srv/modoboa/instance/manage.py logparser works OK (edit: Now crashes on):

Traceback (most recent call last):
  File "/srv/modoboa/instance/manage.py", line 22, in <module>
    execute_from_command_line(sys.argv)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/__init__.py", line 364, in execute_from_command_line
    utility.execute()
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/__init__.py", line 356, in execute
    self.fetch_command(subcommand).run_from_argv(self.argv)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/base.py", line 283, in run_from_argv
    self.execute(*args, **cmd_options)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/base.py", line 330, in execute
    output = self.handle(*args, **options)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/modoboa_stats/management/commands/logparser.py", line 587, in handle
    p.process()
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/modoboa_stats/management/commands/logparser.py", line 552, in process
    for line in self.f.readlines():
  File "/srv/modoboa/env/lib/python2.7/codecs.py", line 314, in decode
    (result, consumed) = self._buffer_decode(data, self.errors, final)
UnicodeDecodeError: 'utf8' codec can't decode byte 0xed in position 1815: invalid continuation byte

/srv/modoboa/env/bin/python /srv/modoboa/instance/manage.py update_statistics fails with:

Traceback (most recent call last):
  File "/srv/modoboa/instance/manage.py", line 22, in <module>
    execute_from_command_line(sys.argv)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/__init__.py", line 364, in execute_from_command_line
    utility.execute()
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/__init__.py", line 356, in execute
    self.fetch_command(subcommand).run_from_argv(self.argv)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/base.py", line 283, in run_from_argv
    self.execute(*args, **cmd_options)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/django/core/management/base.py", line 330, in execute
    output = self.handle(*args, **options)
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/modoboa_stats/management/commands/update_statistics.py", line 84, in handle
    self.update_account_creation_stats(options["rebuild"])
  File "/srv/modoboa/env/local/lib/python2.7/site-packages/modoboa_stats/management/commands/update_statistics.py", line 79, in update_account_creation_stats
    rrdtool.update(str(db_path), *data)
rrdtool.OperationalError: /srv/modoboa/rrdfiles/new_accounts.rrd: illegal attempt to update using time 1564599600 when last update time is 1564599600 (minimum one second step)

[Salamek]

@tonioo I just changed line https://github.com/modoboa/modoboa-stats/blob/a60929b578c2d4f66ddb65249de63e816790d504/modoboa_stats/management/commands/logparser.py#L56

To

self.f = io.open(self.logfile, encoding="utf-8", errors="ignore")  # Ignores unknown characters (You can use "replace" to replace unknown characters)

As a hotfix and everything works again! ... i can create PR if you want ?

[tonioo]

@Salamek Ignoring encoding errors can lead to data loss according to python documentation... I'm not sure it's the right way to fix this if we want accurate stats.

[Salamek]

@tonioo only way we can get non UTF-8 characters in mail.log is from Email Subject/From name snippet inserted into log...

1. We dont need to process email Subjects/From name in stats (?)
2. I have feeling that current logparser will ignore this logline anyway (?)
3. errors="ignore" will only ignore unknown characters, for example Accueil - Les D�lices du Valplessis will become Accueil - Les Dlices du Valplessis
4. errors="replace" will only replace unknown characters with ?, for example Accueil - Les D�lices du Valplessis will become Accueil - Les D?lices du Valplessis

errors="something" is only sane way how to work with UTF-8 files where is chance for mixed encoding... i dont see any sane way to solve this than errors="replace" (or ignore, but ? seems a better option than just ignoring it).

Other options are just too crazy :smile: and just not worth the trouble...

[tonioo]

@Salamek indeed. But since we can non ascii characters in address and domain now, I wonder how the script will behave...

[Salamek]

@tonioo IDN is(should be) converted to punycode... so still ASCII for us...

[mundschenk-at]

I got a similar error tonight: UnicodeDecodeError: 'utf-8' codec can't decode byte 0xc3 in position 2515: invalid continuation byte. The rought cause in the logfile appears to be an issue with an invalid domain name.

postfix/trivial-rewrite[49231]: warning: midna_domain_to_ascii_create: Problem translating domain [...] to ASCII form: UIDNA_ERROR_DISALLOWED

The logparser should handle UTF-8 exceptions gracefully, there's nothing I can do to prevent error messages containing such invalid snippets from being inserted.