Error: Doc not found in list: reywood_publish-composite.js line 210

[martinhbramwell]

This error only appears in my Cucumber log, seems not to affect my app in any way and does not reference any code in my app. Meteor-publish-composite seems to be a dependency of some other package; I did not add it explicitly myself. Perhaps it is a accident waiting to happen :

Exception in queued task: Error: Doc not found in list: 7bJXeKfHTwos7Ekc8
  at [object Object].addChildPub (/tmp/meteor-test-run49uzxg/.meteor/local/build/programs/server/packages/reywood_publish-composite.js:210:15)
  at Publication.createChildPublication (/tmp/meteor-test-run49uzxg/.meteor/local/build/programs/server/packages/reywood_publish-composite.js:136:28)
  at Array.forEach (native)
  at Function._.each._.forEach (/tmp/meteor-test-run49uzxg/.meteor/local/build/programs/server/packages/underscore.js:139:11)
  at Publication._publishChildrenOf (/tmp/meteor-test-run49uzxg/.meteor/local/build/programs/server/packages/reywood_publish-composite.js:134:7)
  at Object.added (/tmp/meteor-test-run49uzxg/.meteor/local/build/programs/server/packages/reywood_publish-composite.js:86:22)
  at [object Object].observeChangesCallbacks.added (/tmp/meteor-test-run49uzxg/.meteor/local/build/programs/server/packages/minimongo.js:3901:28)
  at self.applyChange.added (/tmp/meteor-test-run49uzxg/.meteor/local/build/programs/server/packages/minimongo.js:3801:44)
  at /tmp/meteor-test-run49uzxg/.meteor/local/build/programs/server/packages/mongo.js:1852:30
  at Array.forEach (native)

I'd like to know if I am the only one seeing this. If you need further details, I'll be happy to oblige.

I'm running it in a Xubuntu 14.04 client guest of a KVM virtual machine. It appears exactly four times, one immediately after the other, and only during startup of my Cucumber/Velocity testing.

[reywood]

Hmmm, that is a brain buster. After reviewing the code, I can't figure out how that's possible unless there is some test code that produces a document with a mutating _id field. If you can figure out what package depends on this one, that might help.

[reywood]

Closing for now. Feel free to re-open if a reproduction for this issue is found.

[serkandurusoy]

FWIW I seem to get this a lot and can't actually pin it down somewhere. Feels as if it is related to publications getting teared down as logged in user changes, since all my publications require this.userId

I20151210-00:20:01.881(2)? Exception in queued task: Error: Doc not found in list: v4jSeZJXqntEAZy8f
I20151210-00:20:01.882(2)?     at [object Object].addChildPub (packages/reywood_publish-composite/packages/reywood_publish-composite.js:201:1)
I20151210-00:20:01.882(2)?     at Publication.createChildPublication (packages/reywood_publish-composite/packages/reywood_publish-composite.js:127:1)
I20151210-00:20:01.882(2)?     at Array.forEach (native)
I20151210-00:20:01.882(2)?     at Function._.each._.forEach (packages/underscore/underscore.js:105:1)
I20151210-00:20:01.883(2)?     at Publication._publishChildrenOf (packages/reywood_publish-composite/packages/reywood_publish-composite.js:125:1)
I20151210-00:20:01.883(2)?     at Object.added (packages/reywood_publish-composite/packages/reywood_publish-composite.js:77:1)
I20151210-00:20:01.884(2)?     at [object Object].observeChangesCallbacks.added (packages/minimongo/observe.js:153:1)
I20151210-00:20:01.885(2)?     at self.applyChange.added (packages/minimongo/observe.js:53:1)
I20151210-00:20:01.885(2)?     at packages/mongo/observe_multiplex.js:183:1
I20151210-00:20:01.885(2)?     at Array.forEach (native)

[javascriptlove]

@reywood I just updated to publish-composite:1.7.1 (on Meteor 1.8.1) and started seeing this error. I saw that there is a check for this.documents[key] in the code, is it something that you've been aware of previously? Any idea how to debug this issue?

I20190723-14:10:28.263(2)? Exception in callback of async function: Error: Doc not found in list: Prf_test
I20190723-14:10:28.263(2)?     at PublishedDocumentList.addChildPub (packages/reywood:publish-composite/lib/published_document_list.js:26:19)
I20190723-14:10:28.264(2)?     at Publication.createChildPublication (packages/reywood:publish-composite/lib/publication.js:117:32)
I20190723-14:10:28.265(2)?     at Array.forEach (<anonymous>)
I20190723-14:10:28.265(2)?     at Function._.each._.forEach (packages/underscore.js:139:11)
I20190723-14:10:28.265(2)?     at Publication._publishChildrenOf (packages/reywood:publish-composite/lib/publication.js:115:11)
I20190723-14:10:28.265(2)?     at observeHandle.cursor.observe.added.Meteor.bindEnvironment.doc (packages/reywood:publish-composite/lib/publication.js:54:26)
I20190723-14:10:28.265(2)?     at runWithEnvironment (packages/meteor.js:1286:24)
I20190723-14:10:28.266(2)?     at Object.added (packages/meteor.js:1299:14)
I20190723-14:10:28.266(2)?     at _CachingChangeObserver.added (packages/minimongo/local_collection.js:1305:28)
I20190723-14:10:28.266(2)?     at added (packages/minimongo/local_collection.js:707:29)
I20190723-14:10:28.266(2)?     at runWithEnvironment (packages/meteor.js:1286:24)
I20190723-14:10:28.266(2)?     at packages/meteor.js:1299:14
I20190723-14:10:28.266(2)?     at packages/mongo/observe_multiplex.js:207:9
I20190723-14:10:28.266(2)?     at _IdMap.forEach (packages/id-map/id-map.js:51:35)
I20190723-14:10:28.266(2)?     at ObserveMultiplexer._sendAdds (packages/mongo/observe_multiplex.js:199:22)
I20190723-14:10:28.267(2)?     at ObserveMultiplexer.kadira_Multiplexer_sendAdds [as _sendAdds] (packages/meteorhacks_kadira.js:3690:29)
I20190723-14:10:28.267(2)?     at packages/mongo/observe_multiplex.js:50:12
I20190723-14:10:28.267(2)?     at runWithEnvironment (packages/meteor.js:1286:24)
I20190723-14:10:28.269(2)?     at Object.task (packages/meteor.js:1299:14)
I20190723-14:10:28.270(2)?     at Meteor._SynchronousQueue.SQp._run (packages/meteor.js:917:16)
I20190723-14:10:28.270(2)?     at packages/meteor.js:894:12

[tcastelli]

Having the same problem since last update and was also having trouble debugging this. Any ideas why would it start complaining with the last version? @reywood In our case this error appears to happen only asfter hot code pushes

I20190807-17:57:39.635(2)? Exception in callback of async function: Error: Doc not found in list: XCZLHjoC8rQ9YviZq
I20190807-17:57:39.635(2)?     at PublishedDocumentList.addChildPub (packages/reywood:publish-composite/lib/published_document_list.js:26:19)
I20190807-17:57:39.635(2)?     at Publication.createChildPublication (packages/reywood:publish-composite/lib/publication.js:117:32)
I20190807-17:57:39.636(2)?     at Array.forEach (<anonymous>)
I20190807-17:57:39.636(2)?     at Function._.each._.forEach (packages/underscore.js:139:11)
I20190807-17:57:39.636(2)?     at Publication._publishChildrenOf (packages/reywood:publish-composite/lib/publication.js:115:11)
I20190807-17:57:39.636(2)?     at observeHandle.cursor.observe.added.Meteor.bindEnvironment.doc (packages/reywood:publish-composite/lib/publication.js:54:26)
I20190807-17:57:39.636(2)?     at runWithEnvironment (packages/meteor.js:1286:24)
I20190807-17:57:39.636(2)?     at Object.added (packages/meteor.js:1299:14)
I20190807-17:57:39.636(2)?     at _CachingChangeObserver.added (packages/minimongo/local_collection.js:1305:28)
I20190807-17:57:39.636(2)?     at added (packages/minimongo/local_collection.js:707:29)
I20190807-17:57:39.636(2)?     at runWithEnvironment (packages/meteor.js:1286:24)
I20190807-17:57:39.636(2)?     at packages/meteor.js:1299:14
I20190807-17:57:39.636(2)?     at packages/mongo/observe_multiplex.js:182:30
I20190807-17:57:39.636(2)?     at Array.forEach (<anonymous>)
I20190807-17:57:39.637(2)?     at Function._.each._.forEach (packages/underscore.js:139:11)
I20190807-17:57:39.637(2)?     at Object.task (packages/mongo/observe_multiplex.js:176:9)
I20190807-17:57:39.637(2)?     at Meteor._SynchronousQueue.SQp._run (packages/meteor.js:917:16)
I20190807-17:57:39.637(2)?     at packages/meteor.js:894:12

[javascriptlove]

@reywood @martinhbramwell Guys, someone has to reopen this, the issue persists with latest available version

[jorisroling]

+1

[kswilliames]

+1

[jorisroling]

I've found that using the selector function reactive, it is runs (because of Tracker.autorun) too often and prevents going to the next page. By being careful with assigning to those ReactiveVars only when actually changed (see below) this is prevented.

I use this code (both server & client):

import { ReactiveVar } from 'meteor/reactive-var'
import equal from 'fast-deep-equal'

ReactiveVar.prototype.setIfChanged = function(val) {
  if (!equal(val,this.get())) {
    return this.set(val)
  }
}

and then use <ReactiveVar>.setIfChanged(value) to make the selector only be called (autoran) when actual new values arrive.

Hope it helps!

[kswilliames]

Thanks @jorisroling I'll look into the rate the subscription is being called, it seems like it's refreshing as new data comes from higher containers. It didn't seem to have this problem before the latest update to meteor-publish-composite

[SimonSimCity]

I can confirm that this bug is also present using Meteor 1.8.1 and this package in version 1.7.0.

My stack-trace just looks a little different because I'm using cultofcoders:redis-oplog - which is why you find this here in the stack trace.

Exception in callback of async function: Error: Doc not found in list: A6L9wjekBBYv4vmTC
    at PublishedDocumentList.addChildPub (packages/reywood:publish-composite/lib/published_document_list.js:26:19)
    at Publication.createChildPublication (packages/reywood:publish-composite/lib/publication.js:98:32)
    at Array.forEach (<anonymous>)
    at Function._.each._.forEach (packages/underscore.js:139:11)
    at Publication._publishChildrenOf (packages/reywood:publish-composite/lib/publication.js:96:11)
    at observeHandle.cursor.observe.added.Meteor.bindEnvironment.doc (packages/reywood:publish-composite/lib/publication.js:45:26)
    at runWithEnvironment (packages/meteor.js:1286:24)
    at Object.added (packages/meteor.js:1299:14)
    at _CachingChangeObserver.added (packages/minimongo/local_collection.js:1305:28)
    at added (packages/minimongo/local_collection.js:707:29)
    at runWithEnvironment (packages/meteor.js:1286:24)
    at packages/meteor.js:1299:14
    at packages/cultofcoders:redis-oplog/lib/mongo/ObserveMultiplex.js:232:42
    at Array.forEach (<anonymous>)
    at Function._.each._.forEach (packages/underscore.js:139:11)
    at Object.task (packages/cultofcoders:redis-oplog/lib/mongo/ObserveMultiplex.js:215:15)
    at Meteor._SynchronousQueue.SQp._run (packages/meteor.js:917:16)
    at packages/meteor.js:894:12

[reywood]

If someone can create a small example project that reproduces this bug, I'm happy to have a look.

[SimonSimCity]

I haven't seen it again in the past month, but that doesn't say much. We've had a big spike that day I got the error; the past month was rather quiet. Seems like it's a very tough race-condition. I'll keep you posted as I see it again, but it's definitively there - please reopen.

[SimonSimCity]

@reywood @filipenevola can someone please reopen it, because this still is a bug, and the exception still occurs at least once a week.

I'll now start forking the project by adding more logs to when what and how this could happen.

[filipenevola]

@SimonSimCity done.

[tpmh31292]

I'm having the same problem. Using Meteor 1.8.1 / cultofcoders:redis-oplog 2.0.2 / publish-composite 1.7.1 Stack trace quite similar to @SimonSimCity. You have any updates please?

Exception in callback of async function: Error: Doc not found in list: EsXPNyv8wuxPLkXtM
at PublishedDocumentList.addChildPub (packages/reywood:publish-composite/lib/published_document_list.js:26:19)
at Publication.createChildPublication (packages/reywood:publish-composite/lib/publication.js:117:32)
at Array.forEach (<anonymous>)
at Function._.each._.forEach (packages/underscore.js:139:11)
at Publication._publishChildrenOf (packages/reywood:publish-composite/lib/publication.js:115:11)
at observeHandle.cursor.observe.added.Meteor.bindEnvironment.doc (packages/reywood:publish-composite/lib/publication.js:54:26)
at runWithEnvironment (packages/meteor.js:1286:24)
at Object.added (packages/meteor.js:1299:14)
at _CachingChangeObserver.added (packages/minimongo/local_collection.js:1305:28)
 at added (packages/minimongo/local_collection.js:707:29)
at runWithEnvironment (packages/meteor.js:1286:24)
at packages/meteor.js:1299:14
at packages/cultofcoders:redis-oplog/lib/mongo/ObserveMultiplex.js:256:18
at _IdMap.forEach (packages/id-map/id-map.js:51:35)
at ObserveMultiplexer._sendAdds (packages/cultofcoders:redis-oplog/lib/mongo/ObserveMultiplex.js:249:26)
at packages/cultofcoders:redis-oplog/lib/mongo/ObserveMultiplex.js:68:18

[SimonSimCity]

@tpmh31292 you can help us - e.g. by taking my fork of this package, import it as a custom-override and share your insight 😉 I've just added a bunch of logging data in case it fails: https://github.com/SimonSimCity/meteor-publish-composite/commit/0f37777cd49c493a69c6f380ddab2d6e306dcb6e I'm running this in production trying to get more details ...

[adamgins]

Was anything resolved here. I am seeing this under load too

[SimonSimCity]

@adamgins would you be willing to include my patch and share the details? You can just create a copy of this package into the packages folder of your project which will then be used instead of the package from atmosphere (https://guide.meteor.com/writing-atmosphere-packages.html#overriding-atmosphere-packages)

[adamgins]

@SimonSimCity will do soon and get back to you

[StorytellerCZ]

@SimonSimCity @adamgins any new insight into this issue and a potential fix?

[SimonSimCity]

@StorytellerCZ I have to admit that my focus for private and business projects has shifted away from Meteor. For this reason, I won't be able to provide any new insights without substantial effort.