long term storage of pl/energy-skate-park failed

[liammulh]

One of the errors I saw when investigating #374 was long term storage of pl/energy-skate-park failed. I am not sure if this is related to #374 or if it is a separate issue. For now, I am going to assume it is a separate issue until I find evidence to the contrary.

[liammulh]

Here is the error message in context:

Feb 23 02:21:01 phet-server2.int.colorado.edu rosetta[375109]: info: post request received for /submitTranslation
Feb 23 02:21:01 phet-server2.int.colorado.edu rosetta[375109]: info: sending pl/energy-skate-park translation to be prepared for long-term storage
Feb 23 02:21:01 phet-server2.int.colorado.edu rosetta[375109]: info: preparing translation of pl/energy-skate-park for long-term storage
Feb 23 02:21:01 phet-server2.int.colorado.edu rosetta[375109]: info: adding back dots to translation form data from client
Feb 23 02:21:01 phet-server2.int.colorado.edu rosetta[375109]: info: making translation file contents for energy-skate-park
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: getting sim metadata
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: returning sim metadata mutex
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: using cached sim metadata
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: returning sim metadata
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: getting sim names and titles
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: returning sim names and titles
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: made translation file contents for energy-skate-park; returning them
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: making translation file contents for joist
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: getting sim metadata
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: returning sim metadata mutex
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: using cached sim metadata
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: returning sim metadata
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: getting sim names and titles
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: returning sim names and titles
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: made translation file contents for joist; returning them
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: making translation file contents for scenery-phet
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: getting sim metadata
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: returning sim metadata mutex
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: using cached sim metadata
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: returning sim metadata
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: getting sim names and titles
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: returning sim names and titles
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: made translation file contents for scenery-phet; returning them
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: prepared translation of pl/energy-skate-park for long-term storage
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: sending pl/energy-skate-park translation to be stored long-term
Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: error: long term storage of pl/energy-skate-park failed

[liammulh]

We see:

sending pl/energy-skate-park translation to be stored long-term

This gets logged here:

rosetta/src/server/translationApi/api/submitTranslation.js

Lines 29 to 52 in 4abf1fe

	logger.info( `sending ${req.body.locale}/${req.body.simName} translation to be stored long-term` );
	const longTermStorageRes = await storeTranslationLongTerm( preparedTranslation );
	if ( longTermStorageRes ) {
	reportObjectCache.setDirtyObject( req.body.locale, req.body.simName );
	const wasDeleted = deleteSavedTranslation( {
	userId: req.body.userId,
	simName: req.body.simName,
	locale: req.body.locale
	} );
	if ( wasDeleted ) {
	logger.info( 'previously saved translation deleted' );
	}
	else {
	logger.warn( 'either deletion of previously saved translation failed or there was no previously saved translation' );
	}
	const buildRequestRes = await requestBuild( req.body.simName, req.body.locale, req.body.userId );
	if ( buildRequestRes ) {
	logger.info( 'build request succeeded' );
	}
	submitted = buildRequestRes;
	}
	else {
	logger.error( `long term storage of ${req.body.locale}/${req.body.simName} failed` );
	}

It seems we are not entering the if block on line 31. We are entering the else block on line 50.

[liammulh]

In storeTranslationLongTerm, the first log we see is storing translation of strings in ${repo} long-term:

rosetta/src/server/translationApi/storeTranslationLongTerm.js

Lines 22 to 32 in 4abf1fe

	const storeTranslationLongTerm = async preparedTranslation => {
	let longTermStorageRes = null;
	if ( privateConfig.PERFORM_STRING_COMMITS ) {
	const contents = preparedTranslation.translationFileContents;
	for ( const repo of Object.keys( contents ) ) {
	// check to see if the object is not empty (i.e. strings were translated in repo)
	if ( Object.keys( contents[ repo ] ).length !== 0 ) {
	logger.info( `storing translation of strings in ${repo} long-term` );

After Feb 23 02:21:01, the first instance of this log is:

Feb 23 06:49:56 phet-server2.int.colorado.edu rosetta[375109]: info: storing translation of strings in beers-law-lab long-term

So it seems the if block on line 30 was not entered for:

Feb 23 02:21:02 phet-server2.int.colorado.edu rosetta[375109]: info: sending pl/energy-skate-park translation to be stored long-term

[liammulh]

I will add logs to submitTranslation and storeTranslationLongTerm.

[liammulh]

I saw this over the weekend:

Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: post request received for /submitTranslation
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: attempting to submit translation
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: sending pl/area-builder translation to be prepared for long-term storage
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: preparing translation of pl/area-builder for long-term storage
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: adding back dots to translation form data from client
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: making translation file contents for area-builder
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: getting sim metadata
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: returning sim metadata mutex
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: using cached sim metadata
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: returning sim metadata
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: getting sim names and titles
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: returning sim names and titles
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: made translation file contents for area-builder; returning them
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: making translation file contents for joist
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: getting sim metadata
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: returning sim metadata mutex
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: using cached sim metadata
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: returning sim metadata
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: getting sim names and titles
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: returning sim names and titles
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: made translation file contents for joist; returning them
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: making translation file contents for vegas
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: getting sim metadata
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: returning sim metadata mutex
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: using cached sim metadata
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: returning sim metadata
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: getting sim names and titles
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: returning sim names and titles
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: made translation file contents for vegas; returning them
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: prepared translation of pl/area-builder for long-term storage
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: sending pl/area-builder translation to be stored long-term
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: attempting to store translation long term
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: attempting to perform string commits
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: iterating over area-builder
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: iterating over joist
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: iterating over vegas
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: storage response not null: false
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: done attempting to store translation long term
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: error: long-term storage of pl/area-builder failed
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: translation was submitted: false
Feb 25 00:30:06 phet-server2.int.colorado.edu rosetta[3774860]: info: done attempting to submit translation

[liammulh]

Neither of the objects in the array of objects Octonode returns (stored in longTermStorageRes) contains a status code for the GitHub API response.

[liammulh]

It's hard to debug this without a status code. It's not high priority, but eventually we should stop using octonode and start using octokit. I created #383.

[liammulh]

There's not much to do with this other than monitor and do #383. Un-assigning.

[liammulh]

I saw 6 instances of this since starting up again on March 9th. We need to distinguish between GitHub errors and translation file contents not being stored because (as in #376 (comment)) they are empty (i.e. Object.keys( contents[ repo ] ) === 0).