Inconsistent results when checking length of returned collection

[ruevaughn]

My collection that is being returned sometimes has only two items in the array, but more than often it has three. Here is my code

import { PublicationCollector } from 'meteor/johanbrook:publication-collector';
import { chai, assert } from 'meteor/practicalmeteor:chai';
import { Communities } from '/imports/collections/communities.jsx'
import { Random } from 'meteor/random';
import { resetDatabase } from 'meteor/xolvio:cleaner';
import { _ } from 'meteor/stevezhu:lodash';

if (Meteor.isServer) {
  describe('communities', function () {
    before( () => {
      resetDatabase()

      _.times(3, () => {
         Factory.create("community");
      });
  })

    after( () => {
      resetDatabase()
    })

    it('publishes all communities', function (done) {
      const collector = new PublicationCollector();

       collector.collect('communities', (collections) => {
         console.log("\n\nCOMMUNITIES BEFORE\n\n")
         console.log(Communities.find().fetch() )
         console.log("\n\nCOMMUNITIES AFTER\n\n")
         console.log(collections)

         chai.assert.typeOf(collections.communities, 'array');
         chai.assert.equal(collections.communities.length, 3);
         done();
        });
    });
  });
};

Usually this passing fine, but about 1/5 times it returns with an error saying expected 3 items in array, got 2.

Refreshing once or twice, I then get the correct results

Here is my console logs of the incorrect results

And here is the console log of the correct results

So it seems like sometimes, collections.communities is just returning only two, since a straight database calls shows all three are actually in there. Any Idea?

[ruevaughn]

Apparently if I add Meteor._sleepForMs(10) Right after I add the collections, it has not returned the wrong value once.

before( () => {
  resetDatabase()

  _.times(3, () => {
     Factory.create("community");
  });
  Meteor._sleepForMs(10)
})

[johanbrook]

Hi! Thanks for the detailed description. Will have a look.

[PhilippSpo]

Kind of late to the party, but I have a problem that is probably related to this:

I have two tests that both use the same instance of PublicationCollector. The first test runs just fine, but when the second test runs, the callback of the first test gets called also. This results in the following error:

Error: done() called multiple times

One would need to unsubscribe the callback after a test has finished. AFAIK there is no way of doing this yet in this library.
Example code:

describe.only('Experiences', () => {
  const collector = new PublicationCollector()

  beforeEach(() => {
    // reset database
    Experiences.remove({})

    // setup database
    Experiences.insert(myExperience)
    Experiences.insert(otherExperience)
  })

  describe('publications', () => {
    it('first test', (done) => {
      collector.collect('Experiences', (collections) => {
        // this callback gets called again once the second test runs
        expect(collections.experiences).to.have.lengthOf(2)
        done()
      })
    })

    it('second test', (done) => {
      collector.collect('Experiences', (collections) => {
        expect(collections.experiences).to.have.lengthOf(2)
        done()
      })
    })
  })
})

[johanbrook]

@PhilippSpo Thanks, but are these two related? Is it worked around by instantiating a new collector object for each test case?

[PhilippSpo]

@johanbrook I think maybe both could be resolved by having the possibility to unsubscribe the callback from publication changes.
If I create a instance per test it sometimes works, and sometimes I get the error that @ruevaughn described:

AssertionError: expected [ Array(1) ] to have a length of 2 but got 1

Something to note here: When I log out the content of the collection inside of the publication, I get an Array of 2 documents for both tests (which is exactly what is expected). In the collector callback of the second test however I only get 1 document.

[roberto-naharro]

I have the same problem... It sems the method collect returns the collections values before the subscriptions is ready. This is my code:

properties.ts

import { Properties } from '../../../both/collections/properties.collection';
import { Meteor } from 'meteor/meteor';

Meteor.publish('properties', () => Properties.find());

Meteor.publish('property', function(propertyId: string) {
  return Properties.find({ _id: propertyId });
});

propertes.test.ts

import { resetDatabase } from '../../../both/methods/common.test';
import * as faker from 'faker';
import { Factory } from 'meteor/dburles:factory';
import { PublicationCollector } from 'meteor/johanbrook:publication-collector';
import { _ } from 'meteor/stevezhu:lodash';

import { Properties } from '../../../both/collections/properties.collection';
import { Property } from '../../../both/interfaces/property.interface';
import './properties';

Factory.define('property', Properties, {
  title: () => 'Property ' + faker.lorem.sentence(),
});

describe('Properties - Mutators', function() {
  it('builds correctly from factory', function() {
    resetDatabase();
    const property: Property = Factory.create('property');
    chai.assert.typeOf(property, 'object');
    chai.assert.match(property.title, /^Property /);
  });
});

describe('Properties - Pubications test', function() {
  let randId = faker.random.uuid();

  before(function(done) {
    resetDatabase(function() {
      Factory.create('property', { _id: randId });
      _.times(9, function() {
        Factory.create('property');
      });
      done();
    });
  });

  it('Check properties publication', function(done) {
    const collector = new PublicationCollector();

    collector.collect('properties', (collections) => {
      chai.assert.equal(collections.properties.length, 10);
      done();
    });
  });

  it('Check property publication', function(done) {
    const collector = new PublicationCollector();
    collector.collect('property', randId, (collections) => {
      chai.assert.equal(collections.properties.length, 1);
      done();
    });
  });
});

collections.properties.length sometimes is empty, sometimes 2, sometimes 8, sometimes 3... It is impossible to do any trusty test with this behavior.

[johanbrook]

I actually encounter this in the tests for this package as well .. :>

[roberto-naharro]

I have investigated a little more about it but I didn't find anything. Can you do something to wait until the cursor finish to retrieve all documents before calling ready? Packages like spiderable do something similar to wait to all the data be sended before generating the page.

[PhilippSpo]

@johanbrook @roberto-naharro
So I have done some digging and testing and was able to resolve the issue. I am happy to provide a PR if you agree. This is basically how I was able to track down the root cause of this problem:

I cloned this repo and manipulated the tests so that I only have 2 tests, that are identical. The tests are both subscribing to a subscription and checking the documents count when the ready event is emitted and thus the callback is called:

describe.only('Collect', () => {
    beforeEach(() => {
      Documents.remove({});
      _.times(10, () => Documents.insert({foo: 'bar'}));
    });

    it('should collect documents from a publication', (done) => {
      const collector = new PublicationCollector();

      collector.collect('publication', collections => {
        assert.equal(collections.documents.length, 10, 'collects 10 documents');
        done();
      });
    });

    // exactly the same as the previous test
    it('2 - should collect documents from a publication', (done) => {
      const collector = new PublicationCollector();

      collector.collect('publication', collections => {
        assert.equal(collections.documents.length, 10, 'collects 10 documents');
        done();
      });
    });
});

Then I did some modifications to the PublicationCollector:

• generate a unique ID or each collector for easy identification
• add logs to the ready event
• add logs to the added, changed and removed events

Now when the tests run we can consistently see these logs (format < collectorId > - < event > < documentId > < documentCount >):

 PublicationCollector
   Collect
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added 5M7pDoyZ4M8CNa6uy 1
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added jBeCnqSNjG5jA3YZq 2
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added Xf2mDGzz4csBs9bPK 3
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added JAyPnhdAE8iQH5PsL 4
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added YhCWNJ2XCYw8XFE3p 5
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added FayAiD5RuiqP8chiN 6
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added m6tGt4hexXcsJmgDn 7
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added Zuy4TGQeZ3Q6FcLAa 8
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added kscajqhRWCC2AnB8t 9
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added FPXBwj3uPLD6rLazL 10
f63e7757-3a21-4296-a3a1-4dd3d36b740c is ready 10
     ✓ should collect documents from a publication
f63e7757-3a21-4296-a3a1-4dd3d36b740c - removed 5M7pDoyZ4M8CNa6uy 9
f63e7757-3a21-4296-a3a1-4dd3d36b740c - removed jBeCnqSNjG5jA3YZq 8
f63e7757-3a21-4296-a3a1-4dd3d36b740c - removed Xf2mDGzz4csBs9bPK 7
f63e7757-3a21-4296-a3a1-4dd3d36b740c - removed JAyPnhdAE8iQH5PsL 6
f63e7757-3a21-4296-a3a1-4dd3d36b740c - removed YhCWNJ2XCYw8XFE3p 5
f63e7757-3a21-4296-a3a1-4dd3d36b740c - removed FayAiD5RuiqP8chiN 4
f63e7757-3a21-4296-a3a1-4dd3d36b740c - removed m6tGt4hexXcsJmgDn 3
f63e7757-3a21-4296-a3a1-4dd3d36b740c - removed Zuy4TGQeZ3Q6FcLAa 2
f63e7757-3a21-4296-a3a1-4dd3d36b740c - removed kscajqhRWCC2AnB8t 1
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added t9SHSd5e3FeJuZgEd 1
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added EMruHfwYy9bmgWvqk 2
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added Dsk74s34FKXDAHRhP 3
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added wQDga9vir6fGvmrF6 4
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added FJDNkZREiec7o7Xj9 5
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added 2CGJDWsbyFFLNz8G9 6
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added kBfQxfHGDh2fdatgw 7
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added jr5xvJwMrFhzLHGd8 8
580dae2f-918d-4325-85f7-6c57007caa73 - added t9SHSd5e3FeJuZgEd 1
580dae2f-918d-4325-85f7-6c57007caa73 - added EMruHfwYy9bmgWvqk 2
580dae2f-918d-4325-85f7-6c57007caa73 - added Dsk74s34FKXDAHRhP 3
580dae2f-918d-4325-85f7-6c57007caa73 - added wQDga9vir6fGvmrF6 4
580dae2f-918d-4325-85f7-6c57007caa73 - added FJDNkZREiec7o7Xj9 5
580dae2f-918d-4325-85f7-6c57007caa73 - added 2CGJDWsbyFFLNz8G9 6
580dae2f-918d-4325-85f7-6c57007caa73 - added kBfQxfHGDh2fdatgw 7
580dae2f-918d-4325-85f7-6c57007caa73 - added jr5xvJwMrFhzLHGd8 8
580dae2f-918d-4325-85f7-6c57007caa73 is ready 8
     1) 2 - should collect documents from a publication
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added hEYSyKQG3fXJPduW3 9
580dae2f-918d-4325-85f7-6c57007caa73 - added hEYSyKQG3fXJPduW3 9
f63e7757-3a21-4296-a3a1-4dd3d36b740c - added SSJPRgmwdPiHPL3Ds 10
580dae2f-918d-4325-85f7-6c57007caa73 - added SSJPRgmwdPiHPL3Ds 10
 1 passing (246ms)
 1 failing
 1) PublicationCollector Collect 2 - should collect documents from a publication:
    AssertionError: collects 10 documents: expected 8 to equal 10

Observations:

• everything looks fine for the first subscription/test. All 10 documents get added and then the ready event is emitted, thus making the test succeed.
• before the second test, our beforeEach is executed, which removes all documents and adds 10 new ones. This results in 10 removed events for the first subscription
• when the second subscription/test runs, however, we see that for both subscriptions we get (only) 8 added events, then the ready event get's emitted and after that we see two more added events for both subscriptions.

This indeed is a very unexpected behaviour and I am still not a 100% sure why this is happening.

edit: In the meteor source code in a comment, it says that "_publishCursor only returns after the initial added callbacks have run". Maybe we found an edge case here where this is not true...

The problem seems to be, that we are not unsubscribing after we are done observing one publication. The _publishCursor method (which is called on a cursor that got returned from the publication handler) returns an observeHandle object that can be used to unsubscribe from the publication by calling its' stop method.

This means that the problem can be fixed by collection all observeHandles for every PublicationCollector and unsubscribing all of them once the ready event has been emitted. I adapted the collect method to do exactly that.

collect(name, ...args) {

    const handler = Meteor.server.publish_handlers[name];
    const result = handler.call(this, ...args);

    if (_.isFunction(args[args.length - 1])) {
      const callback = args.pop();
      this.on('ready', (collections) => {
        console.log(`${this.id} is ready`, collections.documents.length);
        callback(collections);
        this.observeHandles.forEach(handle => handle.stop());
      });
    }

    // TODO -- we should check that result has _publishCursor? What does _runHandler do?
    if (result) {
      // array-ize
      this.observeHandles = [].concat(result).map(cur => cur._publishCursor(this));
      this.ready();
    }
}

If we now run the tests again we see the following logs 🎉:

 PublicationCollector
   Collect
64c27c75-0101-447d-9005-de59a137debc - added yYTXs7y4nvFTuB3kh 1
64c27c75-0101-447d-9005-de59a137debc - added 73rhB5ueJem6YBkzb 2
64c27c75-0101-447d-9005-de59a137debc - added 2cfN9A8dw4n7pdxod 3
64c27c75-0101-447d-9005-de59a137debc - added rvdnhAG5LkeiGy4Pc 4
64c27c75-0101-447d-9005-de59a137debc - added x9N6AL5Ft4gDyzGN6 5
64c27c75-0101-447d-9005-de59a137debc - added AbBysMWiwaR3htHd8 6
64c27c75-0101-447d-9005-de59a137debc - added qHHHiTbAozJgoB9Bz 7
64c27c75-0101-447d-9005-de59a137debc - added Mb6FupfNqodAN3Dp3 8
64c27c75-0101-447d-9005-de59a137debc - added WQ2sP2bvrfyBAHMJW 9
64c27c75-0101-447d-9005-de59a137debc - added fZL65DsQyHWQMGHXQ 10
64c27c75-0101-447d-9005-de59a137debc is ready 10
     ✓ should collect documents from a publication
8dd7e0fb-4321-4ced-a688-20fb00b7d49e - added 4WCxM7CnBKoM6nyFA 1
8dd7e0fb-4321-4ced-a688-20fb00b7d49e - added Sn9CgMFTnFufq9Kik 2
8dd7e0fb-4321-4ced-a688-20fb00b7d49e - added neZXj8gtoZa9YMwJ2 3
8dd7e0fb-4321-4ced-a688-20fb00b7d49e - added ZecFq96wmh6ftYzTg 4
8dd7e0fb-4321-4ced-a688-20fb00b7d49e - added 6cCcKXWwNW2aSQoAP 5
8dd7e0fb-4321-4ced-a688-20fb00b7d49e - added cLmYXN9v96uCwHTnc 6
8dd7e0fb-4321-4ced-a688-20fb00b7d49e - added niTCXtvpYygyJ7n6M 7
8dd7e0fb-4321-4ced-a688-20fb00b7d49e - added f39xG5NywwqQ8duNe 8
8dd7e0fb-4321-4ced-a688-20fb00b7d49e - added b6j9ngYicKE9Kha8d 9
8dd7e0fb-4321-4ced-a688-20fb00b7d49e - added BrybxySZbQW9rfwRc 10
8dd7e0fb-4321-4ced-a688-20fb00b7d49e is ready 10
     ✓ 2 - should collect documents from a publication
 2 passing (60ms)

[johanbrook]

Very good digging, @PhilippSpo ! 👏 It makes very much sense with cleaning up observe handles afterwards. Ugh for internal, undocumented Meteor methods .. :)

If you could provide a PR with the documented fix I'd be happy to test and merge ⚡

[johanbrook]

Published as johanbrook:publication-collector@1.0.1, test and reopen if you're still getting this. Thanks again!

[ruevaughn]

Great work guys and thanks! I will give it a test and let you know if I have any issues.