unicode issues in the logging

[hakavlad]

thrash-protect freezed my browser and crashed:

ERROR:root:red alert!  unacceptable time delta observed! interval: 0.5 cooldown_counter: 1 expected delay: 0 delta: 0.0579028129578 time: 1552623249.83 frozen pids: [(28299,)]
ERROR:root:red alert!  unacceptable time delta observed! interval: 0.5 cooldown_counter: 3 expected delay: 0 delta: 0.0423080921173 time: 1552623249.87 frozen pids: [(28299,), (28928,)]
ERROR:root:red alert!  unacceptable time delta observed! interval: 0.5 cooldown_counter: 5 expected delay: 0 delta: 0.0360288619995 time: 1552623250.0 frozen pids: [(28299,), (28928,), (29415,)]
Traceback (most recent call last):
  File "./thrash-protect.py", line 560, in <module>
    main()
  File "./thrash-protect.py", line 556, in main
    thrash_protect(args)
  File "./thrash-protect.py", line 531, in thrash_protect
    current.unfrozen_pid = unfreeze_something()
  File "./thrash-protect.py", line 505, in unfreeze_something
    log_unfrozen(pid_to_unfreeze)
  File "./thrash-protect.py", line 435, in log_unfrozen
    logfile.write("%s - unfrozen   pid %5s - %s - list: %s\n" % (get_date_string(), str(pid), get_process_info(pid), frozen_pids))
UnicodeEncodeError: 'ascii' codec can't encode characters in position 107-113: ordinal not in range(128)

[tobixen]

Oups, that's a bad one

[hakavlad]

see also rfjakob/earlyoom#110

Handle line with unicode:

with open('/proc/' + pid + '/stat', 'rb') as f:
    line = f.read().decode('utf-8', 'ignore')

[tobixen]

We're already doing decode there ... at least in master branch):

        ## TODO: we should fetch this information from /proc filesystem instead of using ps
        info = check_output("ps -p %d uf" % pid, shell = True).decode('utf-8')

[tobixen]

The decode is there in the v0.12.1 revision as well, though it was not there in the original pull-request. It was apparently introduced in pull request #6, 2016. So unless you're running a very old version of thrash-protect, the issue must be somewhere else. I should try and see if I can reproduce the issue.

[hakavlad]

We're already doing decode

...without 'ignore'.

Please use decode('utf-8', 'ignore') instead of decode('utf-8')

you're running a very old version

I used the latest version. I cloned it today.
thrash-protect.py 0.12.1

[tobixen]

I've fixed the ignore, but I don't believe that will help.

Is there any difference if you run it under python2 or python3?

[hakavlad]

I added 'ignore' and it doesn't help.

Traceback (most recent call last):
  File "./thrash-protect.py", line 560, in <module>
    main()
  File "./thrash-protect.py", line 556, in main
    thrash_protect(args)
  File "./thrash-protect.py", line 528, in thrash_protect
    freeze_something()
  File "./thrash-protect.py", line 451, in freeze_something
    pids_to_freeze = pids_to_freeze or global_process_selector.scan()
  File "./thrash-protect.py", line 389, in scan
    ret = self.collection[self.scan_method_count % len(self.collection)].scan()
  File "./thrash-protect.py", line 337, in scan
    stats = self.readStat(fn)
  File "./thrash-protect.py", line 204, in readStat
    stats_tx = stat_file.readline()
  File "/usr/local/lib/python3.6/codecs.py", line 321, in decode
    (result, consumed) = self._buffer_decode(data, self.errors, final)
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xd1 in position 21: invalid continuation byte

It needs multiple fixes.

[hakavlad]

Instead of
stats_tx = stat_file.readline()
maybe need to try
stats_tx = stat_file.read().decode('utf-8', 'ignore').split('\n')

[hakavlad]

Bad idea: AttributeError: 'str' object has no attribute 'decode'.

[tobixen]

The character set should be given when opening the file. However, as I read the error above it assumes UTF-8, but carps because the file is not valid UTF8.

I will need to try to reproduce this charset problems somehow.

[tobixen]

How does a typical non-ascii /proc/*/stat file look for you?

[tobixen]

the only thing there that is non-numeric is the process name. I'll see if I can spawn up a process locally that has a non-ascii name.

[hakavlad]

it works with python and python3

        with open(sfn, 'rb') as stat_file:
            stats=[]
            stats_tx = stat_file.read().decode('utf-8', 'ignore')

[hakavlad]

reproduce this charset problems

Rename memory hog to ПАГПАВОНАВЧАОНАЛ and execute it.

[hakavlad]

reproduce this charset problems

cd /tmp
ln -s /usr/bin/tail ./ЙЦУКЕНГШЩЗХ
./ЙЦУКЕНГШЩЗХ /dev/zero

[hakavlad]

need to handle next

Traceback (most recent call last):
  File "./thrash-protect.py", line 560, in <module>
    main()
  File "./thrash-protect.py", line 556, in main
    thrash_protect(args)
  File "./thrash-protect.py", line 531, in thrash_protect
    current.unfrozen_pid = unfreeze_something()
  File "./thrash-protect.py", line 505, in unfreeze_something
    log_unfrozen(pid_to_unfreeze)
  File "./thrash-protect.py", line 435, in log_unfrozen
    logfile.write("%s - unfrozen   pid %5s - %s - list: %s\n" % (get_date_string(), str(pid), get_process_info(pid), frozen_pids))
UnicodeEncodeError: 'ascii' codec can't encode characters in position 90-100: ordinal not in range(128)

[tobixen]

I guess the problem is a bit further up ...

with open("/var/log/thrash-protect.log", 'a') as logfile:

[tobixen]

I believe it should work now. Tested at my end at least, without problems.

[tobixen]

oh, except now things are breaking under python2

[tobixen]

and now there are test breakages

[tobixen]

unit tests mended, ref c56ba65

[tobixen]

I've been digging a bit more into this - I'd say it could almost be classified as a kernel bug. In the stat file, long command names are truncated - and in this case, the truncation happens right in a UTF-8 character. The Ш-character is two bytes long in UTF-8, d0a8 - but the truncation happens between d0 and a8. Hence the decode('utf-8') without the ignore-flag will indeed break.

I had forgotten we actually had unit tests in place, I'll make sure to include this process name in the test code.