Skip to content
This repository has been archived by the owner on Aug 31, 2019. It is now read-only.

3.4 - lot of {"debug":"","code":0} in logs #13

Closed
alexbainbridge opened this issue Feb 10, 2017 · 19 comments · Fixed by Kinvey/js-sdk#128
Closed

3.4 - lot of {"debug":"","code":0} in logs #13

alexbainbridge opened this issue Feb 10, 2017 · 19 comments · Fixed by Kinvey/js-sdk#128

Comments

@alexbainbridge
Copy link

Steps to Reproduce

When running latest version, I am seeing a lot of {"debug":"","code":0} in the logs

Expected Result

Not seeing these debug entries

Version of Kinvey HTML5 SDK

3.4

Pretty sure this message is coming from Kinvey, but can't be 100% sure !

@alexbainbridge
Copy link
Author

Turns out may not be Kinvey related but from another library. Sorry!

@thomasconner
Copy link
Contributor

No worries Alex

@alexbainbridge
Copy link
Author

alexbainbridge commented Feb 16, 2017

Actually! Now seeing a lot of {"debug":"","code":-1} (And I am back having a level of confidence that its coming from Kinvey)

Seems to be when I have 2 network searches quickly in succession (tens of milliseconds between), from same device. Inconsistent though, mainly does not report this error (and works as expected)

That error is the error (JSON version) that is going to the error catch from a collection search query.

When I get that error, I am NOT seeing the request going to baas.kinvey - so my feeling is that the error is in query creation somewhere in the client library.

i.e.

  • Network request 1 - always works
  • Network request 2 - 95% of time works, 5% of time get the error, no request sent to baas.kinvey in these situations

Any thoughts? (or at least, do you recognise a debug error response and is it possible for the library to provide more detail as to what to look for....) Is this something left in the code your end from your development?

Currently on 3.4.0

@alexbainbridge
Copy link
Author

Interestingly, I can recreate this exact error code by sending a mal-formed field list to the collection query. Means it could be my code of course.....

What I am really asking for is that you provide a bit more meat on the error message as right now its hard to know where to start

@thomasconner
Copy link
Contributor

@alexbainbridge I agree a better error message would help. Do you have some sample code that can recreate this issue?

@alexbainbridge
Copy link
Author

alexbainbridge commented Feb 16, 2017

Incorrect

query.fields = ['_id', 'items_json']+'.'+ui_lang;

(with e.g. ui_lang sent to a string such as en, turns out that the field filtering works on secondary level values not just top level columns.... which is GREAT)

when I meant to do this which is correct

query.fields = ['_id', 'items_json'+'.'+ui_lang];

That gets the same error message, 100% of the time.

Of course I have fixed that (!), but its the same error message as when something that I can't find causes an error, hence at least (perhaps) points at the area of code that creates the error..... making it possible to add more meat to the error response...

Thanks!

@thomasconner
Copy link
Contributor

I did the following

var store = Kinvey.DataStore.collection('books');
var query = new Query();
query.fields = ['_id', 'items_json']+'.en';
store.find(query)
  .subscribe(function(result) {
    console.log(result);
  }, function(error) {
    console.log(error.name, error.message);
  });

I saw the following message printed QueryError fields must be an Array. Please see our troubleshooting guide for more information on errors.

@alexbainbridge
Copy link
Author

Yeah that one was. The ORIGINAL one though, which is 5% intermittent, who knows. I will keep plugging away! (I wonder if showing the original query that the client THOUGHT it was, in the error message, would be helpful, if saying the query is malformed)..... its never creating network traffic so the evaluation has to be within the client library itself

@thomasconner
Copy link
Contributor

What does the code look like where you log this error?

@alexbainbridge
Copy link
Author

The answer is "its complicated" ;)

I have a user update, a search, a second search (with different criteria, excluding those found on the first search, i.e. ensuring that something is found if the first search doesn't come up with much). Due to the asynchronous nature of this, hard to know exactly what happens in what order as some are not done in then sections of code.

Its the second search that is intermittently failing

OK - this is on me - I will see if I can work out how to make it a constantly fail rather than intermittent fail. I can probably do this with logging my end. 50/50 this will be my end or your end!

Leave this open, let me come up with something more specific, then we can take this forwards!

Thanks Thomas

@alexbainbridge
Copy link
Author

Right now I have parked solving this problem - if I get exactly that error on the 2nd search - I just run the query again, and it works...... which although is not really going to help you get to the root cause, is good enough for my situation and the user experience is not impacted (although 200ms later)

Its not network connectivity, its not logic our end (otherwise rerunning wouldn't make it work). Its something else! But it is something....

@alexbainbridge
Copy link
Author

alexbainbridge commented Apr 16, 2017

OK - I have worked out what the error is (now that with the latest version of client library the full Kinvey error is showing)

"originalStack":"Error\n at NoActiveUserError.g (http://localhost:8100/build/polyfills.js:3:7133)\n at NoActiveUserError.ExtendableBuiltin (http://localhost:8100/build/main.js:142374:9)\n at NoActiveUserError.ExtendableError (http://localhost:8100/build/main.js:142404:120)\n at NoActiveUserError.BaseError (http://localhost:8100/build/main.js:20983:108)\n at new NoActiveUserError

(not full message)

Hypothesis - it seems that when doing multiple search queries on the same page, with a query processed early in the queue that updates the Kinvey user collection..... IF that update happens to hit at the same time as a later query, the later query has no active user.... as these updates are async, its hard to know what will hit when. i.e. potentially why its only on one of our use cases

Ideally I guess the client library should not have a period in the active user update where there is no active user set ? (assuming its this)

Version 3.4.5

@alexbainbridge
Copy link
Author

@alexbainbridge
Copy link
Author

On the support forum message one comment is "I have a custom end point that queries a couple collections and returns. "

Hence that is also an example of multiple queries on the same page running perhaps concurrently? Sounds a similar concept to what I am doing

Slightly clutching at straws :)

@thomasconner
Copy link
Contributor

Good find @alexbainbridge. We will take a look at our code used to store and update the active user.

@alexbainbridge
Copy link
Author

Thanks @thomasconner

For completeness, the full error message

{"originalStack":"Error\n at NoActiveUserError.g (http://localhost:8100/build/polyfills.js:3:7133)\n at NoActiveUserError.ExtendableBuiltin (http://localhost:8100/build/main.js:142409:9)\n at NoActiveUserError.ExtendableError (http://localhost:8100/build/main.js:142439:120)\n at NoActiveUserError.BaseError (http://localhost:8100/build/main.js:20983:108)\n at new NoActiveUserError (http://localhost:8100/build/main.js:162426:119)\n at Object.session (http://localhost:8100/build/main.js:99634:42)\n at KinveyRequest.getAuthorizationHeader (http://localhost:8100/build/main.js:99725:28)\n at KinveyRequest.execute (http://localhost:8100/build/main.js:99755:19)\n at KinveyObservable._subscribe (http://localhost:8100/build/main.js:52563:24)\n at KinveyObservable.Observable._trySubscribe (http://localhost:8100/build/main.js:24166:25)\n at KinveyObservable.Observable.subscribe (http://localhost:8100/build/main.js:24154:27)\n at http://localhost:8100/build/main.js:42455:22\n at t.invoke (http://localhost:8100/build/polyfills.js:3:14529)\n at Object.onInvoke (http://localhost:8100/build/main.js:4425:37)\n at t.invoke (http://localhost:8100/build/polyfills.js:3:14469)","zoneAwareStack":"Error\n at NoActiveUserError.g (http://localhost:8100/build/polyfills.js:3:7133)\n at NoActiveUserError.ExtendableBuiltin (http://localhost:8100/build/main.js:142409:9)\n at NoActiveUserError.ExtendableError (http://localhost:8100/build/main.js:142439:120)\n at NoActiveUserError.BaseError (http://localhost:8100/build/main.js:20983:108)\n at new NoActiveUserError (http://localhost:8100/build/main.js:162426:119)\n at Object.session (http://localhost:8100/build/main.js:99634:42)\n at KinveyRequest.getAuthorizationHeader (http://localhost:8100/build/main.js:99725:28)\n at KinveyRequest.execute (http://localhost:8100/build/main.js:99755:19)\n at KinveyObservable._subscribe (http://localhost:8100/build/main.js:52563:24)\n at KinveyObservable.Observable._trySubscribe (http://localhost:8100/build/main.js:24166:25)\n at KinveyObservable.Observable.subscribe (http://localhost:8100/build/main.js:24154:27)\n at http://localhost:8100/build/main.js:42455:22\n at t.invoke (http://localhost:8100/build/polyfills.js:3:14529)\n at Object.onInvoke (http://localhost:8100/build/main.js:4425:37)\n at t.invoke (http://localhost:8100/build/polyfills.js:3:14469)","stack":"Error: There is not an active user. Please login a user and retry the request.\n at g (http://localhost:8100/build/polyfills.js:3:7133)\n at NoActiveUserError.BaseError (http://localhost:8100/build/main.js:20990:19)\n at new NoActiveUserError (http://localhost:8100/build/main.js:162426:119)\n at Object.session (http://localhost:8100/build/main.js:99634:42)\n at KinveyRequest.getAuthorizationHeader (http://localhost:8100/build/main.js:99725:28)\n at KinveyRequest.execute (http://localhost:8100/build/main.js:99755:19)\n at KinveyObservable._subscribe (http://localhost:8100/build/main.js:52563:24)\n at KinveyObservable.Observable._trySubscribe (http://localhost:8100/build/main.js:24166:25)\n at KinveyObservable.Observable.subscribe (http://localhost:8100/build/main.js:24154:27)\n at http://localhost:8100/build/main.js:42455:22\n at t.invoke (http://localhost:8100/build/polyfills.js:3:14529)\n at Object.onInvoke (http://localhost:8100/build/main.js:4425:37)\n at t.invoke (http://localhost:8100/build/polyfills.js:3:14469)\n at n.run (http://localhost:8100/build/polyfills.js:3:9741)\n at NgZone.run (http://localhost:8100/build/main.js:4294:62)","debug":"","code":-1,"__zone_symbol__currentTask":{"type":"microTask","state":"notScheduled","source":"Promise.then","zone":"angular","cancelFn":null,"runCount":0}}

@alexbainbridge
Copy link
Author

Hi @thomasconner if you get a few seconds to take a peek at this (and the support forums issue that sounds similar) would be great! Workaround I (and the support forum person) have put in is workable, but creates a momentary poor user experience, and would rather avoid it if you could fix it :)

@thomasconner
Copy link
Contributor

@alexbainbridge Sorry for the delay. I am will work on having a fix out for this in the next release. I expect to have this release out in the next week or two. I will update this issue when the release it out with the fix.

@thomasconner
Copy link
Contributor

Fixed with release 3.5.1

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants