search

gadicc / meteor-messageformat

MessageFormat i18n support for Meteor, with reactive templates
54 stars 22 forks source link

sort objects by key when saving mfAll.js #195

Closed 1u closed 8 years ago

1u commented 8 years ago

instead of natural order.

this helps keeping commits of mfAll.js small, and gives better overview of changes.

gadicc commented 8 years ago

Good call, this makes a lot of sense. Released in ui.8.

1u commented 8 years ago

not sure yet what it is, but some thing is broken... :/ can't really reproduce. :( keys got shifted around while text stayed.

     "category.theatre": {
       "key": "category.theatre",
       "lang": "en",
-      "text": "Theater",
-      "ctime": "2015-06-18T00:13:15.000Z",
-      "mtime": "2015-06-18T00:13:15.000Z",
-      "revisionId": "7caSDtPWmZ4m9Mm2h",
-      "file": "client/lib/mfFixedTranslations.html",
-      "line": 55,
-      "template": "mfFixedTranslations",
-      "_id": "ckSLb9tt5fFxkcKRY"
+      "text": "Files: (optional)",
+      "ctime": "2016-01-22T03:43:04.000Z",
+      "mtime": "2016-01-22T03:43:04.000Z",
+      "revisionId": "CwNucoAm5j3vCPNj5",
+      "file": "client/views/events/event.edit.html",
+      "line": 129,
+      "template": "eventEdit",
+      "_id": "WqorRuDHSr7TzawZT"
     },

there were duplicate en keys in the mfStrings-collection once correct once wrong... coming from extract file maybe..

gadicc commented 8 years ago

That sounds pretty serious. I can't seem to reproduce though. Did this happen on the upgrade to ui.8? I released later that day ui.9, which could also be a suspect.

Can you show me an example of the duplicate keys? And their corresponding entries in mfAll.js, if any?

Thanks!

sbalmer commented 8 years ago

Sorry for the long delay. We have a hard time pinning it down. Sometimes some translations in the native language seem to get replaced by other text when extracting and loading from mfAll.js. I'm sorry I'm unable to provide a clear repro for this, it seems to be a timing issue.

One thing I've been able to reproduce is a small quirk which may be related to this. If I run this command:

rm server/extracts.msgfmt*; meteor reset && meteor

Meteor starts running but is interrupted midway, I think because the server/extracts.msgfmt file was created. I know that the file usually is created once, so the interruption would only happen on the very first run. Looks like this:

I20160210-03:04:27.000(1)? 2016-02-10 03:04:26.887 info:  [msgfmt:extracts]  429 string(s) added, 0 changed, and 0 marked as removed.
=> Meteor server restarted                    
I20160210-03:04:37.063(1)? 2016-02-10 03:04:37.061 info:  [msgfmt:extracts]  415 string(s) added, 0 changed, and 0 marked as removed.

The curious thing here is the second line with "415 added", which is slightly lower than the full count.

I'll try to find a repro which is a bit more stable than what we have so far.

1u commented 8 years ago

here is some log of what i have tried tonight:

    {
    "_id" : "YSczi6CBrrvatxtPs",
    "key" : "email.verificationFailed",
    "lang" : "en",
    "text" : "Address could not be verified",
    "ctime" : ISODate("2016-02-09T23:16:29.000Z"),
    "mtime" : ISODate("2016-02-09T23:16:29.000Z"),
    "revisionId" : "xZrWmgWtYXgjXCeGE",
    "file" : "client/start.js",
    "line" : 128,
    "func" : "function(error)"
    }

    {
    "_id" : "xZrWmgWtYXgjXCeGE",
    "lang" : "en",
    "key" : "email.verificationFailed",
    "text" : "Address could not be verified",
    "ctime" : ISODate("2016-02-09T23:16:29.000Z")
    }

searching in files for this wrong key -> finding it once in source: 

addMessage(mf("email.verificationFailed", "Address could not be verified"), 'danger')

once in mfAll.js: 

    server/mfAll.js:
        "key": "email.verificationFailed",
        "lang": "en",
        "text": "Address could not be verified",
        "ctime": "2015-12-17T23:07:28.000Z",
        "mtime": "2015-12-17T23:07:28.000Z",

and twice in server/extracts.msgfmt~:

"course.edit.title":{"key":"course.edit.title","lang":"en","text":"Address could not be verified","ctime":"2016-02-09T23:16:29.000Z","mtime":"2016-02-09T23:16:29.000Z","revisionId":"eTKC7xRkg2pHxt5gs","file":"client/start.js","line":128,"func":"function(error)","_id":"HEsA2Ppcfaq8m2Lnm"}

"email.verificationFailed":{"key":"email.verificationFailed","lang":"en","text":"Address could not be verified","ctime":"2016-02-09T23:16:29.000Z","mtime":"2016-02-09T23:16:29.000Z","revisionId":"xZrWmgWtYXgjXCeGE","file":"client/start.js","line":128,"func":"function(error)","_id":"YSczi6CBrrvatxtPs"}

twice in extracts_renamed.msgfmat~:

"course.history.created_by":{"key":"course.history.created_by","lang":"en","text":"Address could not be verified","ctime":"2016-01-27T14:45:49.000Z","mtime":"2016-02-09T23:17:04.362Z","revisionId":"hkhp3Y3iodvLnoyeS","file":"client/start.js","line":128,"func":"function(error)","removed":true,"_id":"uGvdx74jM48dECZWM"}

"email.verificationFailed":{"key":"email.verificationFailed","lang":"en","text":"Address could not be verified","ctime":"2016-02-03T01:08:21.000Z","mtime":"2016-02-03T01:08:21.000Z","revisionId":"AXLQELzBsoELYmZcF","file":"client/start.js","line":128,"func":"function(error)","_id":"QpPnEDweoj4M4tPHp"}

and once only in extracts_renamed_2.msgfmat~:

"course.edit.title":{"key":"course.edit.title","lang":"en","text":"Address could not be verified","ctime":"2016-02-09T23:16:29.000Z","mtime":"2016-02-09T23:16:29.000Z","revisionId":"eTKC7xRkg2pHxt5gs","file":"client/start.js","line":128,"func":"function(error)","_id":"HEsA2Ppcfaq8m2Lnm"}

now i cant think any more :sleepy:

1u commented 8 years ago

how come there is always one string removed even if i don't change anything? ´[msgfmt:extracts] 0 string(s) added, 0 changed, and 1 marked as removed´

1u commented 8 years ago

anyone? :/

gadicc commented 8 years ago

hey @1u, sorry, I'm overseas at the moment but this is on my list! trying to find a free moment to look at this properly. will be in touch.

1u commented 8 years ago

@gadicc: thx! very appreciated. We spent quite a lot of time not figuring out what's happening. If you pull openki I'm quite sure you can reproduce. But I hope you can already guess the problem by reading what happened in the procedure described above. See you

1u commented 8 years ago

@gadicc: can you estimate when?

gadicc commented 8 years ago

I've spent a few mornings on this but no luck yet... i wish there was a clearer way to reproduce. The good news is I'm back from my trip (today is my first day back at work), and I'd like to try resolve this by the end of this week.

All I've noticed so far is that all the "wrong" strings are removed strings, except they don't seem to be initially marked as such. I'm using this code to try find wrong stuff:

  msgfmt.findDupeText = function() {

    var strings = msgfmt.strings.en;
    var texts = {};

    for (var key in strings) {
      var str = strings[key];
      if (!texts[str.text])
        texts[str.text] = [];
      texts[str.text].push(str.key);
    }

    for (var text in texts) {
      if (texts[text].length > 1) {
        console.log('dupe: ' + text);
        _.each(texts[text], function(key) {
          console.log('  * ' + key + (strings[key].removed ? ' (removed)' : ''));
        });
      }
    }
  }

Except from what you've said you're finding "wrong" strings that are keys that are actually being used and being displayed. I can't find any like this, after trying all sorts of things. What I didn't think though, is, are you only noticing this on your deployed instance (and never your local one?). I didn't try deploying, although I can try this next. Where is translation (via mf:ui) done? on local or deployed instance? If deployed, do you copy from mfAll.js from there?

Can you also confirm that you've been on the same version for a while and this happens in that same version? I had a thought it could be from the core.15 -> core.16 upgrade, but looking at the code, I don't see how... would just like you to confirm it's not related to this though.

sbalmer commented 8 years ago

Thanks for looking into it. After spending some more time on it, I can give you more info that should narrow the field considerably. The mixed strings show up only in the native language, and I observed the fault by clearing the DB and the extracts.msgfmt* files. So when I start meteor this way:

 rm server/extracts.msgfmt*; meteor reset; meteor

I have a good chance of observing mixed strings later. In the trace-log the key -> text mapping is good, but in the extracts.msgfmt~ file it is mixed up. Here is an example of how it looks, the lines prefixed with [msgfmt:extracts] are from the trace log, the others are from extracts.msgfmt~.

[msgfmt:extracts]  * find.showFilters: "Filter"

    "find.showFilters": {
        "_id": "nm7sp76uhAcLvWmdw",
        "ctime": "2016-01-28T01:08:22.000Z",
        "file": "client/lib/mfFixedTranslations.html",
        "key": "find.showFilters",
        "lang": "en",
        "line": 62,
        "mtime": "2016-01-28T01:08:22.000Z",
        "revisionId": "23A4wsA56y3fRvabk",
        "template": "mfFixedTranslations",
        "text": "Cooking"
    },

[msgfmt:extracts]  * event.no_event: "Sorry, we couldn't find this event, it must have been deleted or it never existed in the first place."

    "event.no_event": {
        "_id": "A5Ap529uTdaBYHhQG",
        "ctime": "2016-03-02T00:35:42.000Z",
        "file": "client/views/find/find.html",
        "key": "event.no_event",
        "lang": "en",
        "line": 28,
        "mtime": "2016-03-02T00:35:42.000Z",
        "revisionId": "hfowMwm9PX9fxHxD6",
        "template": "find",
        "text": "Filter"
    },

[msgfmt:extracts]  * category.cooking: "Cooking"

    "category.cooking": {
        "ctime": "2016-01-12T23:47:53.000Z",
        "file": "client/views/login/resetPassword.html",
        "key": "passwordReset.label.password",
        "lang": "en",
        "line": 15,
        "mtime": "2016-01-12T23:47:53.000Z",
        "revisionId": "W42eYb2WxPJ9zFQLS",
        "template": "resetPassword",
        "text": "Password"
    },

In the first two cases the entries seem to have the wrong key. In the last case an entry looks good but is listed under the wrong key ( "category.cooking" vs "passwordReset.label.password"). The wrong keys lead to wrong translations in the interface, so for example the "Filter" button is labeled "Cooking" instead.

I still don't know where exactly the mangling happens. I attached the full version of both files.

msgfmt.trace.txt extracts.msgfmt.txt

1u commented 8 years ago

Hey, thanks gadi

Here are some more (small) clarifications:

You can check an instance with broken keys on https://staging.openki.net/?lg=en

One more hint is that broken strings are not totally mixed up: sometimes it's obvious when e.g. explanation1, explanation2, explanation4 and explanation5 is replaced with category4 category5 category6 and category7.

here is what version we were using when (updated core on Jan.12th from 14 to 17 and ui from 6 to 7 and not touched since) first stumbled upon error on Jan. 27th when testing ui.8 locally. So it might be something with core-update..

(mfAll.js was last touched Jan. 12th. aswell)

So you are able to reproduce the error? Did you clone our repo? Are you reproducing it as well in a new small project?

cheers

gadicc commented 8 years ago

Hey guys, I'll be back on this (and the other msgfmt issues) tomorrow morning.... (GMT+2)

sbalmer commented 8 years ago

Ok I think I found some more clues. If I only delete extracts.msgfmt~ but not extracts.msgfmt and I remove the "Fibering" of the syncAll I cannot observe any clobbering.

diff --git a/msgfmt:core/lib/mfPkg/messageformat-server.js b/msgfmt:core/lib/mfPkg/messageformat-server.js
index 55231e2..8be2b6f 100644
--- a/msgfmt:core/lib/mfPkg/messageformat-server.js
+++ b/msgfmt:core/lib/mfPkg/messageformat-server.js
@@ -170,7 +170,6 @@ mfPkg.addNative = function(strings, meta) {

 // called from mfTrans.js
 mfPkg.syncAll = function(strings, meta) {
-  new Fiber(function() {
     var startTime = Date.now();

     var lastSync = msgfmt.mfMeta.findOne('syncTrans');
@@ -189,7 +188,6 @@ mfPkg.syncAll = function(strings, meta) {
     msgfmt.observeFrom(meta.updatedAt, 'trans');

     log.debug('Finished syncAll (in a fiber) in ' + (Date.now() - startTime) + ' ms');
-  }).run();
 }

 var meta = mfPkg.mfMeta.find().fetch();

So there seem to be two things that cause this.

sbalmer commented 8 years ago

I think the whole raceyness of the thing comes down to the use of the mfPkg.strings cache. The DB collections seem to be consistent, and only the version written from mfPkg.strings to extracts.msgfmt~ sees these mutations. They then get propagated on deploy.

gadicc commented 8 years ago

Hey @1u, @sbalmer.

So firstly, I really wanted to say, thank you both for your help in working to resolve this obviously frustrating issue, for your patience, and continued support of msgfmt in openki :)

TL;DR

Can you try core.19 and extract.13 and see if they work any better for you?

Longer expanation

Tbh, I didn't have that much luck reproducing in my local clone. Either because I'm not as good at identifying them (since you are intimate with the site, mistakes will pop out for you), or perhaps just because it's a race condition and I was just lucky :> I thought looking at duplicate text would make it easy to identify, but I only found bad text in removed keys.

Anyways, the fact that it worked without the Fiber was most interesting. This is definitely a clear suspect, since the timing is out of our control. I've removed the Fiber, but do recall the main issue was load time, so I've made a lot of changes to make us a lot smarter about when we actually need to update or not. Timing data is still there in debug log level, for you to check; successive startups should be significantly faster now.

I've also fixed a lot of small bugs in extracts and done a lot of re-factoring in core. If you could give the versions above a spin and see if things are more stable, that would be great.

MartinFournier commented 8 years ago

Quick note for you if it would help: we've had something like this happen a few times. I think we pinpointed (I think...) it to a faulty git merge of the mfAll.js file. It seemed to be a workflow issue between devs with different text keys in different branches merging.

sbalmer commented 8 years ago

Thanks @gadicc! With core.19 and extract.13 I'm unable to observe the corruption after several tries. I haven't measured but it does seem faster too. So we're very happy here.

@MartinFournier thanks for the tip, we had to deal with a broken mfAll.js merge in the past. Now we only translate on one instance, so it doesn't get merged. Here we saw random corrupted strings on fresh extract/load into DB, only in the native language. Luckily just reloading the mf* collections with the new release made it go away.

gadicc commented 8 years ago

Awesome! Thanks for the testing and reporting back. Really really happy to this resolved now.

@MartinFournier, thanks for that. If you had a loooot of strings, could also have been this issue, as @sbalmer described (it was a race condition so the more strings and the slower your database I/O, the more it would be to see an occurrence). Also, the original point of this issue was to sort mfAll.js by key, for much clearer git diffs.