Tails

#1 Updated by intrigeri 2019-12-17 10:12:35

Interesting!

I can’t reproduce this locally on my sid system (tried on current master and stable branches).
I’ve not seen it happen on Jenkins (Stretch) either:

• https://jenkins.tails.boum.org/view/RM/job/test_Tails_ISO_stable/
• https://jenkins.tails.boum.org/view/RM/job/check_PO_master/

(both failed recently due to a buggy translation in wiki/src/about/contact.pt.po, that I just fixed)

So I’m wondering if there’s anything special on your system, that can possibly make i18nspector or the Python JSON library behave differently.

Did you see this happen only in features/po.feature or can you also reproduce this by running ./submodules/jenkins-tools/slaves/check_po (with the jenkins-tools submodule at the commit tracked by current master or stable) directly?

What does i18nspector --version say?

Random guess: maybe the current locale affects how the underlying code reads PO files. Might be worth retrying with LC_ALL=C or en_US.UTF-8?

Other than that, I must admit I’m quite clueless :/

#2 Updated by CyrilBrulebois 2019-12-18 02:30:33

Going back to the 4.1.1 tag on my system:

kibi@armor:~/work/clients/tails/release/release-checkout$ ./submodules/jenkins-tools/slaves/check_po
ERROR: wiki/src/about/contact.pt.po:
    i18nspector is not happy:
        E: inconsistent-trailing-newlines msgid '[[!toc levels=2]]\n'
checked files are not clean.

with:

kibi@armor:~/work/clients/tails/release/release-checkout$ dpkg -l i18nspector
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name                   Version          Architecture     Description
+++-======================-================-================-==================================================
ii  i18nspector            0.25.2-1         all              checking tool for gettext POT, PO and MO files

kibi@armor:~/work/clients/tails/release/release-checkout$ i18nspector --version
i18nspector 0.25.2
+ Python 3.5.3
+ polib 1.0.8
+ rply 0.7.4

I’m quite surprised to only see that during a test suite run, which I’ve done locally without checking the results in Jenkins because I wasn’t trusted its results anyway… that’s why I’ve been re-running all non-fragile tests locally before taking any actions.

My system is configured with LANG=en_GB.UTF-8 (globally, so the account has that too), and I’ve been running the test suite this way:

sudo TMPDIR=~/TT ./run_test_suite --view --capture --iso ../isos/tails-amd64-4.1.1/tails-amd64-4.1.1.iso -- features/po.feature

I’m quite reassured that the PO files are not as broken as the local test suite run led me to fear in the beginning (even if I couldn’t see why that would be the case).

I’ve rerun the test suite from the same 4.1.1 tag, and it fails in the same way. So yes it’s reproducible at least here, and I’ll investigate a little bit more.

#3 Updated by CyrilBrulebois 2019-12-18 02:55:05

And strace saved the day yet another time:

kibi@armor:~/work/clients/tails/release/release-checkout$ sudo ls -l /root/.cache/rply/i18nspector-intexpr-1-931a22c3200c0cb35da6baca76b3973f7517595a.json
-rw-r--r-- 1 root root 3393 Sep  4 19:42 /root/.cache/rply/i18nspector-intexpr-1-931a22c3200c0cb35da6baca76b3973f7517595a.json

so for some reasons, my system had a cache file dated from the previous release, with broken contents, that is interfering with proper operation?

How to fix? Clean-up the whole cache (might be harsh/interfere with other RPLY users)? See if the cache can be located elsewhere?

Quick looks suggests i18nspector sets its own cache_id (as opposed to letting RPLY set one up randomly if unset), and that RPLY uses this:

        cache_dir = AppDirs("rply").user_cache_dir
        cache_file = os.path.join(
            cache_dir,
            "%s-%s-%s.json" % (
                self.cache_id, self.VERSION, self.compute_grammar_hash(g)
            )
        )

Looking at the appdirs Python module, it seemed that adding something like env={'XDG_CACHE_HOME': '/tmp/shouldberandom'} to the subprocess.run() call might help, and indeed, I’m only seeing the inconsistent-trailing-newlines error in wiki/src/about/contact.pt.po now.

I’m therefore tempted to suggest creating a temporary directory in slaves/lint_po (to which check_po is a symlink), using it for each i18nspector run, and removing it afterwards. This would avoid having to deal with whatever was possibly cached/left over in the calling user’s cache directory.

#4 Updated by intrigeri 2019-12-18 12:38:03

>

> kibi@armor:~/work/clients/tails/release/release-checkout$ sudo ls -l /root/.cache/rply/i18nspector-intexpr-1-931a22c3200c0cb35da6baca76b3973f7517595a.json
> -rw-r--r-- 1 root root 3393 Sep  4 19:42 /root/.cache/rply/i18nspector-intexpr-1-931a22c3200c0cb35da6baca76b3973f7517595a.json
> 

> so for some reasons, my system had a cache file dated from the previous release, with broken contents, that is interfering with proper operation?

FTR, I have that file too. Mine is 3386 bytes large and its mtime is 2015-11-20. I think it’s not a coincidence that the json.decoder.JSONDecodeError you saw triggers in column 3387 (char 3386).

> I’m therefore tempted to suggest creating a temporary directory in slaves/lint_po (to which check_po is a symlink), using it for each i18nspector run, and removing it afterwards. This would avoid having to deal with whatever was cached/left over in the calling user’s cache directory.

Sounds good to me.

#17 Updated by intrigeri 2019-12-21 13:17:52

Hi @hefee,

> Fixed the race condition and do some more cleanup.

LGTM, thanks!

> I still have uploaded to git.tails.boum.org:jenkins-tools, as this was the only source I found I can write to:

Yeah, I think that’s actually the only repo we have for jenkins-tools.

#20 Updated by intrigeri 2020-01-28 12:18:19

hefee, IIRC you suggested a change that would help gather debugging info, but I can’t find it anymore. Any hints?

#24 Updated by CyrilBrulebois 2020-03-18 16:54:53

OK, this is a highly entertaining bug.

Different PO files trigger different code paths in i18nspector. This can be checked using strace and/or by adding some instrumenting in rply/parsergenerator.py:

$ rm -rf ~/.cache/rply && strace -v -o /tmp/fr -s 400 -- i18nspector --language fr wiki/src/getting_started.fr.po && find ~/.cache/rply
I: wiki/src/getting_started.fr.po: boilerplate-in-initial-comments 'Copyright (C) YEAR Free Software Foundation, Inc.'
I: wiki/src/getting_started.fr.po: boilerplate-in-initial-comments 'This file is distributed under the same license as the PACKAGE package.'
I: wiki/src/getting_started.fr.po: boilerplate-in-initial-comments 'FIRST AUTHOR <EMAIL@ADDRESS>, YEAR.'
P: wiki/src/getting_started.fr.po: no-version-in-project-id-version Tails
W: wiki/src/getting_started.fr.po: no-report-msgid-bugs-to-header-field
/usr/bin/find: ‘/home/kibi/.cache/rply’: No such file or directory

$ rm -rf ~/.cache/rply && strace -v -o /tmp/pt -s 400 -- i18nspector --language fr wiki/src/home.pt.po && find ~/.cache/rply
I: wiki/src/home.pt.po: boilerplate-in-initial-comments 'Copyright (C) YEAR Free Software Foundation, Inc.'
I: wiki/src/home.pt.po: boilerplate-in-initial-comments 'This file is distributed under the same license as the PACKAGE package.'
I: wiki/src/home.pt.po: boilerplate-in-initial-comments 'FIRST AUTHOR <EMAIL@ADDRESS>, YEAR.'
W: wiki/src/home.pt.po: language-disparity fr (command-line) != pt (Language header field)
building a parser
considering cache_file: /home/kibi/.cache/rply/i18nspector-intexpr-1-931a22c3200c0cb35da6baca76b3973f7517595a.json
W: wiki/src/home.pt.po: boilerplate-in-project-id-version 'PACKAGE VERSION'
W: wiki/src/home.pt.po: boilerplate-in-language-team 'LANGUAGE <LL@li.org>'
/home/kibi/.cache/rply
/home/kibi/.cache/rply/i18nspector-intexpr-1-931a22c3200c0cb35da6baca76b3973f7517595a.json

So the attempt at splitting the pool into a single “head” and a “long tail” (see below) was a nice idea, but that didn’t ensure the “head” did warm the rply cache: it depends whether the first considered file needs that particular parser (and the relevant cache). On my system, the first file seems to always be the aforementioned (and aptly-named) wiki/src/getting_started.fr.po, which doesn’t need that cache.

I think that pretty much explains why there’s at best an empty rply directory after this file has been processed, and why errors vary between the “existing-but-empty JSON file” and the “being-written JSON file” error cases: the first elements of the “long tail” are racing.

What I call the “head” vs. “long tail” split is (empathic comments are mine):

<code class="python">
            chain = [(_check_po_file(next(iterator)),),                # <=== 1 element, supposedly warming the cache
                     pool.imap_unordered(_check_po_file,iterator, 10)] # <=== all others
</code>

Instead of hardcoding a “known good” file as the first element of the list, I’m tempted to proceed as follows: consider elements one at a time until a file appears in the rply cache. At which time, consider the “slightly longer head” finished, and go for the “slightly less long tail” approach: multiprocess all others through pool.imap_unordered().

While processing elements in turn, if a hard limit of say 50 files is reached, break so that people don’t waste too much time because everything is being processed sequentially: make it obvious that something is going wrong and that one needs to look at this test case (again).

I’ll draft something up shortly.

#25 Updated by CyrilBrulebois 2020-03-18 17:27:17

Patch attached, without a proper commit message, because I think my last comment on the ticket says it all… plus I’m not convinced this is what we should implement. That relies on an implementation detail that might end up being too fragile. :/

#29 Updated by intrigeri 2020-03-19 07:35:51

Wow, amazing detective work!

Code LGTM. Performance on my system is in the same ballpark area as previously.

I will merge this once I’ve seen it pass the corresponding test on Jenkins (I’m not worried it won’t pass, but better safe than sorry :)

In passing, I believe d7ca5acd76c18d2183efaded23174b8750f02843 was perhaps racy: once the with tempfile.TemporaryDirectory context manager exits, tmpdir is removed (asynchronously?), but we used it in poFile.i18nspector(my_env) outside of the context manager. Anyway, it does not matter as this problem disappeared in your follow-up commits :)

> [ FWIW, I’ve capped this at 4 hours, which seems a little high for “just a cache bug”, while still being lower than the >6 effective hours. But I hope we’re no longer going to have to deal with that particular topic, wasting RM’s time during release cycles with random Jenkins failures, but also at release time; “famous last words”, I know… ]

I’d rather see you report the total effective hours: fixing such “holes in the roof” is IMO worth it.

#30 Updated by CyrilBrulebois 2020-03-19 07:48:40

intrigeri wrote:
> Wow, amazing detective work!
>
> Code LGTM. Performance on my system is in the same ballpark area as previously.
>
> I will merge this once I’ve seen it pass the corresponding test on Jenkins (I’m not worried it won’t pass, but better safe than sorry :)

Thanks, and yes, good call. :)

> In passing, I believe d7ca5acd76c18d2183efaded23174b8750f02843 was perhaps racy: once the with tempfile.TemporaryDirectory context manager exits, tmpdir is removed (asynchronously?), but we used it in poFile.i18nspector(my_env) outside of the context manager. Anyway, it does not matter as this problem disappeared in your follow-up commits :)

Possibly, yes. But tests I ran led me to end up with lots of temporary directories (several thousands), so I’ve committed what I tested… before cleaning everything up. :)

> > [ FWIW, I’ve capped this at 4 hours, which seems a little high for “just a cache bug”, while still being lower than the >6 effective hours. But I hope we’re no longer going to have to deal with that particular topic, wasting RM’s time during release cycles with random Jenkins failures, but also at release time; “famous last words”, I know… ]
>
> I’d rather see you report the total effective hours: fixing such “holes in the roof” is IMO worth it.

Fine with me, ta.

#32 Updated by CyrilBrulebois 2020-03-19 08:30:35

Oh, I understand what I was seeing… that’s embarrassing.

Indeed, with the context manager, the temporary directory was created, its named stored, then removed. But its name was then re-used by the rply stack to (re)create the same directory again right after its removal. And since that wasn’t handled by Python as a temporary directory, it would be kept around until the removal of the parent directory (which itself is a temporary directory for the whole runtime)…

So much for trying not to trigger reindentation of long blocks right before cleaning up… Woops!