Meteor method call looping

Question

Short Story:

Meteor method loops if the method executed in more than 120 seconds.

This is how I tested

There is Meteor method called 'build' in server side as below:

'build': function(buildRequest) {

  log.info('method build get called: buildRequest=%s', JSON.stringify(buildRequest));

  shell.exec('echo "simulate long Android build task."');
  shell.exec('sleep ' + buildRequest.sec);

  var result = {'successful': true, 'output': "OK", 'fileName': 'test.apk', 'genFile': '/tmp/test.apk'}

  log.info("method return result=%s", JSON.stringify(result));
  return result;
}

I set route to call this method as below:

this.route('buildApp', {
  where: 'server'
  , action: function() {
    var buildRequest = this.request.query;
    log.info('buildApp: http parameters: ', buildRequest);

    var result = methods.build(buildRequest);
    var response = this.response;

    if (result.successful) {
      methods.download(response, result.genFile, result.fileName);
    }
    else {
      response.writeHead(500, {});
      response.end("server has error: " + result.output);
    }
  }
})

Then, I call url

http://localhost:3000/buildApp?app=test&server=dev&db=DB&appId=test&sec=120

then, build method loops

=> App running at: http://localhost:3000/
I20150109-14:55:45.285(9)? info: buildApp: http parameters:  app=test, server=dev, db=DB, appId=test, sec=120
I20150109-14:55:45.358(9)? info: method build get called: buildRequest={"app":"test","server":"dev","db":"DB","appId":"test","sec":"120"}
I20150109-14:55:45.358(9)? simulate long Android build task.
I20150109-14:57:45.359(9)? info: method return result={"successful":true,"output":"OK","fileName":"test.apk","genFile":"/tmp/test.apk"}
I20150109-14:57:45.387(9)? info: buildApp: http parameters:  app=test, server=dev, db=DB, appId=test, sec=120
I20150109-14:57:45.387(9)? info: method build get called: buildRequest={"app":"test","server":"dev","db":"DB","appId":"test","sec":"120"}
I20150109-14:57:45.446(9)? simulate long Android build task.

I assume it is related this code:

https://github.com/meteor/meteor/blob/096df9d62dc9c3d560d31b546365f6bdab5a87dc/packages/webapp/webapp_server.js#L18

Long story:

I made a simple android app build screen with Meteor. Everything works well however if I submit the form to build app, it builds over and over again. even if I stop server and restart, as soon as server restarted it calls again.

If form filled and submitted, I call Meteor 'build' method. The method will clone git repository and build the app by calling shell script below.

var exec = shell.exec('./genApp.sh ' + buildRequest.appId + " " + buildRequest.server + " " + buildRequest.db);
//var exec = shell.exec('echo "simple task will not loop"');

If I call ./genApp.sh (it will take a few minutes.), then the Meteor 'build' method looping itself. but if I do simple task, it will not loop but executed once.

I added below code at the beginning of build Meteor method to stop it for debugging. But I have no idea what causes this.

      if (a == 1) {
        a = 0;
        throw new Error("Why call again?!");
      }
      ++ a;

the server log:

I20150108-19:48:08.220(9)? info: success
I20150108-19:48:08.221(9)? info: return result=[object Object]
I20150108-19:48:09.034(9)? Exception while invoking method 'build' Error: Why call again?!
I20150108-19:48:09.035(9)?     at [object Object].methods.build (app/javis.js:92:25)
I20150108-19:48:09.035(9)?     at maybeAuditArgumentChecks (packages/ddp/livedata_server.js:1599:1)
I20150108-19:48:09.035(9)?     at packages/ddp/livedata_server.js:648:1
I20150108-19:48:09.035(9)?     at [object Object]._.extend.withValue (packages/meteor/dynamics_nodejs.js:56:1)
I20150108-19:48:09.035(9)?     at packages/ddp/livedata_server.js:647:1
I20150108-19:48:09.035(9)?     at [object Object]._.extend.withValue (packages/meteor/dynamics_nodejs.js:56:1)
I20150108-19:48:09.036(9)?     at [object Object]._.extend.protocol_handlers.method (packages/ddp/livedata_server.js:646:1)
I20150108-19:48:09.036(9)?     at packages/ddp/livedata_server.js:546:1

main source code

var APP_01 = 'app01-andy';
var APP_02 = 'app02-andy';

if (Meteor.isClient) {

  Router.configure({
    layoutTemplate: 'layout'
  })
  Router.map(function() {
    this.route('/', 'home');
  });

  buildRequest = {
    appId: 0
    , server: 'dev'
    , db: 'DEFAULT'
    , app: APP_01
  };

  Session.set('successful',  false);
  Session.set('output', '');
  Session.set('downloadLink', null);

  Template.home.helpers({
    successful: function() {
      return Session.get('successful');
    }
    , output: function() {
      return Session.get('output');
    }
    , downloadLink: function() {
      var successful = Session.get('successful');
      var downloadLink = Session.get('downloadLink');
      console.log(downloadLink);
      if (successful) {
        $('#downloadLink').show();
      } else {
        $('#downloadLink').hide();
      }
      return downloadLink;
    }
  });

  Template.home.events({
    'submit .app-build-form': function() {
      event.preventDefault();

      buildRequest.appId = event.target.appId.value;
      buildRequest.server = event.target.server.value;
      buildRequest.db = event.target.db.value;
      buildRequest.app = event.target.app.value;

      $("#submit").prop('disabled', true);

      Meteor.call('build', buildRequest, function(error, result) {
        console.log(JSON.stringify(result));
        Session.set('successful', result.successful);
        Session.set('output', result.output);
        Session.set('downloadLink', '/downloadApp?fullPathFile='+result.genFile+'&fileName='+result.fileName);
        $("#submit").prop('disabled', false);
        console.log("meteor call end");
      });

      console.log("submit finished");
      // prevent default form submit.
      return false;
    },
    'click #sel_app': function() {
      console.log(event.target.value);
      var app = event.target.value;
      var selDb = $("#sel_db");
      if (app === APP_02) {
        selDb.val('APP_02_DB'); selDb.prop('disabled', true);
      }
      else {
        selDb.prop('disabled', false);
      }
    }
  });
}

if (Meteor.isServer) {

  var shell = Meteor.npmRequire('shelljs');
  var log = Meteor.npmRequire('winston');

  var a = 0;

  var methods = {
    'build': function(buildRequest) {
      if (a == 1) {
        a = 0;
        throw new Error("Why call again?!");
      }
      ++ a;
      log.info(JSON.stringify(buildRequest));
      var dir = shell.pwd();
      log.info("work dir: %s", dir);

      shell.cd('/project/build/');

      var branch = null;
      var app = buildRequest.app;
      if (app === APP_01) {
        branch = '2.0';
      }
      else if (app === APP_02) {
        branch = '1.0';
      }
      else {
        branch = 'master';
      }
      shell.exec('rm -rf ' + buildRequest.app);
      shell.exec('git clone -b '+branch+' ssh://git@company-build.com/'+buildRequest.app+'.git');
      shell.cd(buildRequest.app + "/app");

      var exec = shell.exec('./genApp.sh ' + buildRequest.appId + " " + buildRequest.server + " " + buildRequest.db);
      //var exec = shell.exec('echo "simple task will not loop"');

      var code = exec.code;
      var output = exec.output;

      log.info(code);
      log.info(output);

      var fileName = null;
      var matches = output.match(/The package copied to (.+apk)/);
      var genFile = null;
      if (matches != null && matches.length > 1) {
        genFile = matches[1];
        log.info(genFile);
        // TODO : do not write file in public, http://stackoverflow.com/questions/13201723/generating-and-serving-static-files-with-meteor
        /*
        shell.mkdir(process.env.PWD + '/tmp');
        shell.cp('-f', genFile, process.env.PWD + '/tmp');
        */
        fileName = genFile.substring(genFile.lastIndexOf('/') + 1);
      }
      matches = output.match(/BUILD SUCCESSFUL/);
      var successful = false;
      if (matches != null && matches.length > 0) {
        log.info("success");
        successful = true;
      }

      var result = {'successful': successful, 'output': output, 'fileName': fileName, 'genFile': genFile};

      log.info("return result="+result);
      return result;
    }
    , 'download' : function(response, fullPathFile, fileName) {

      var stat = fs.statSync(fullPathFile);
      response.writeHead(200, {
        'Content-Type': 'application/vnd.android.package-archive'
        , 'Content-Length': stat.size
        , 'Content-Disposition': 'attachment; filename=' + fileName
      });
      fs.createReadStream(result.genFile).pipe(response);
    }
  };

  Meteor.methods(methods);

  fs = Npm.require('fs');

  Router.map(function() {
    this.route('buildApp', {
      where: 'server'
      , action: function() {
        var buildRequest = this.request.query;
        log.info(this.request.query);
        log.info(buildRequest);
        var result = methods.build(buildRequest);
        var response = this.response;

        if (result.successful) {
          methods.download(response, result.genFile, result.fileName);
        }
        else {
          response.writeHead(500, {});
          response.end("server has error: " + result.output);
        }
      }
    }),
    this.route('downloadApp', {
      where: 'server'
      , action: function() {
        var params = this.request.query;
        var fullPathFile = params.fullPathFile;
        var fileName = params.fileName;
        methods.download(this.response, fullPathFile, fileName);
      }
    })
  });

  Meteor.startup(function () {
    // code to run on server at startup
  });
}

What causes the loop? Any help will be appreciated.

Even I call http://localhost:3000/buildApp?app=xxx&server=live&db=DB&appId=12423 , the build loops.

OK if I change ./genApp.sh to simple one to narrow the conditions.

#!/bin/bash

echo "test"
echo "The package copied to /service/release/20150108/existing-file.apk"
echo "BUILD SUCCESSFUL"

sleep 180

It calls again when it sleeps 180 seconds. What make this call again? because I call the url directly. I think there is no client side code retrial.

Answer 1

Hmm... it could be that when shell.exec is run synchronously it "starves the event loop", causing some issues.

The solution would be to use a Future which would allow Meteor to continue running in another Fiber while waiting for shell.exec to complete.

var Future = Npm.require('fibers/future');

Meteor.methods({
'build': function(buildRequest) {
  var fut = new Future(), result;
  log.info('method build get called: buildRequest=%s', JSON.stringify(buildRequest));

  shell.exec('echo "simulate long Android build task."');
  shell.exec('sleep ' + buildRequest.sec, function(code, output){
    fut.return([code, output]);
  });
  result = fut.wait();
  log.info(result[0], result[1])

  var result = {'successful': true, 'output': "OK", 'fileName': 'test.apk', 'genFile': '/tmp/test.apk'}

  log.info("method return result=%s", JSON.stringify(result));
  return result;
}
});

Answer 2

Fool proof way to make this work:

1. Create a Collection to store "Build Requests"
2. Set a timer to occasionally process build requests in a separate Fiber.
3. Notify users of "completed" build requests with yet another collection and publication.

Here's an example of how that might be structured [not bug tested]:

"use strict";

var fs, shell, log, Future;
// need a collection to store build requests & their status
var Builds = new Mongo.Collection('builds');
var APP_01 = 'app01-andy';
var APP_02 = 'app02-andy';

// expose routes to client & server
Router.configure({
  layoutTemplate: 'layout'
});
Router.map(function() {
  this.route('/', 'home');
  this.route('downloadApp', {
    where: 'server'
    , action: function() {
      var params = this.request.query,
          buildId = params.buildId,
          build, stat;
      check(buildId, String); // or Mongo Identifier
      build = Builds.findOne({_id: buildId});
      check(build, Match.ObjectIncluding({
        file: String,
        fileName: String
      }));
      stat = fs.statSync(build.file);
      this.response.writeHead(200, {
        'Content-Type': 'application/vnd.android.package-archive'
        , 'Content-Length': stat.size
        , 'Content-Disposition': 'attachment; filename=' + build.fileName
      });
      fs.createReadStream(build.file).pipe(this.response);
    }
  });
});
if (Meteor.isClient) {

  Session.set('currentBuildId', null);
  Session.set('submittingBuildRequest', false);

  Tracker.autorun(function(){
    // Whenever there is a current build set, subscribe to it.
    var buildId = Session.get('currentBuildId');
    if (buildId != null){
      Meteor.subscribe('build', buildId);
    }
  });

  Template.home.helpers({
    // Use this helper in your template to expose the `state` property (queued, running, success, failed)
    currentBuild: function() {
      var buildId = Session.get('currentBuildId'), build;
      if (buildId == null) return null;
      build = Builds.findOne({_id: buildId});
      if (build == null) return null;
      return build;
    }
  });

  Template.home.events({
    'submit .app-build-form': function(e) {
      var target, buildRequest;
      e.preventDefault();
      target = e.target;

      buildRequest = {
        appId: target.appId.value
        , server: target.server.value
        , db: target.db.value
        , app: target.app.value
      };
      Session.set('submittingBuildRequest', true);

      Meteor.call('requestBuild', buildRequest, function(error, buildId) {
        Session.set('submittingBuildRequest', false);
        if (error != null){
           console.error(error);
        } else {
          console.log("buildId=", JSON.stringify(buildId));
          Session.set('currentBuildId', buildId);
        }
      });
    },
    'click #sel_app': function(e) {
      var app = e.target.value;
      var selDb = $("#sel_db");
      if (app === APP_02) {
        selDb.val('APP_02_DB'); selDb.prop('disabled', true);
      }
      else {
        selDb.prop('disabled', false);
      }
    },
    'click a.downloadCurrentBuild': function(){
      // Alternatively, could create a download url with the "pathFor" template helper
      Router.go('downloadApp', {buildId: Session.get('currentBuildId')})
    }
  });
}

if (Meteor.isServer) {
  fs = Npm.require('fs');
  shell = Meteor.npmRequire('shelljs');
  log = Meteor.npmRequire('winston');
  Future = Npm.require('fibers/future');

  Meteor.publish({
    'build': function(buildId){
      check(buildId, String); // or Mongo Identifier
      return Builds.find({_id: buildId}, {fields: {
        fileName: false, // don't expose real paths to client
        file: false
      }});
    }
  });

  Meteor.methods({
    'requestBuild': function(buildRequest){
      check(buildRequest, {
        appId: Match.Integer,
        server: String, // apply additional restrictions
        db: String, // apply additional restrictions
        app: Match.OneOf(APP_01, APP_02)
      });

      _.extend(buildRequest, {
        state: 'queued'
        // These properties will be set later, just keeping them here for reference
        //, output: null
        //, fileName: null
        //, file: null
      });

      return Builds.insert(buildRequest);
    }
  });


  var Builder = {
    // Alternative: Poll the database for new builds
    //run: function Builder_Run() {
    //  log.info('checking for "queued" builds');
    //  // may need to change this to `fetch` and then loop manually
    //  Builds.find({state: 'queued'}).forEach(Builder.processBuildRequest);
    //  Meteor.setTimeout(Builder.run, 1000); // tail call to run again (after 1 second)
    //},
    exec: function(cmd){
      // Wraps shell.exec so that they don't block the event loop
      var fut = new Future();
      shell.exec(cmd, function(code, output){
        fut.return({code: code, output: output});
      });
      return fut.wait();
    },
    processBuildRequest: function Builder_processBuildRequest(buildRequest) {
      console.log('running buildRequest=', JSON.stringify(buildRequest));
      Builds.update({_id: buildRequest._id}, {
        $set: {
          state: 'running'
        }
      });

      var branch = null;
      if (buildRequest.ap === APP_01) {
        branch = '2.0';
      }
      else if (buildRequest.ap === APP_02) {
        branch = '1.0';
      }
      else {
        branch = 'master';
      }

      shell.cd('/project/build/');
      Builder.exec('rm -rf ' + buildRequest.app);
      Builder.exec('git clone -b ' + branch + ' ssh://git@company-build.com/' + buildRequest.app + '.git');
      shell.cd(buildRequest.app + "/app");
      //var exec = Builder.exec('./genApp.sh ' + buildRequest.appId + " " + buildRequest.server + " " + buildRequest.db)
      var exec = Builder.exec('sleep 180');
      var output = exec.output;

      log.info("code=" + exec.code);
      log.info("output=" + output);

      var fileName = null;
      var matches = output.match(/The package copied to (.+apk)/);
      var file = null;
      if (matches != null && matches.length > 1) {
        file = matches[1];
        log.info("file=" + file);
        fileName = file.substring(file.lastIndexOf('/') + 1);
      }
      matches = output.match(/BUILD SUCCESSFUL/);

      if (matches != null && matches.length > 0) {
        log.info("success");
        Builds.update({_id: buildRequest._id}, {
          $set: {
            state: 'success',
            file: file,
            fileName: fileName,
            output: output
          }
        });
      } else {
        log.info("failed");
        Builds.update({_id: buildRequest._id}, {
          $set: {
            state: 'failed'
          }
        });
      }
    }
  };


  Meteor.startup(function () {
    // code to run on server at startup

    // if using polling method
    //Meteor.setTimeout(Builder.run, 1000); // will poll for new builds every second (unless already running a build)

    // set up an observe [to run forever] to automatically process new builds.
    Builds.find({state: 'queued'}).observe({
      added: Builder.processBuildRequest
    });
  });
}