Lately I found problems with the business logic logger. I don't have clear yet where is the problem, but many times happens that it's not logging everything it is supposed to log.



For example now I wanted to log the data of a loop of async calls... If I log a simple string everything works fine, but if I log an object doesn't anymore.



This:

for(i in docs) {

var record = new Record();

record.get(docs[i]._id, function(err, doc) {

logger.info("test string");

...

});

}



will log a string every time the logger is called... so something like:

"test string"

"test string"

"test string"

"test string"

"test string"







While this:

for(i in docs) {

var record = new Record();

record.get(docs[i]._id, function(err, doc) {

logger.info(doc);

...

});

}



will only log one object, something like:

{

"...": "...",

...

}







At the moment, to get all the logs, I'm logging on an array that I append to the response.body ...it works, but it's not the best solution :)

Is this something you can fix?

Can you provide more of the code? One thing I noticed that is not related- I would not necessarily include the record.get in a for loop. It would be better to create an array of _Ids you want, and query the database once. Additionally, in Kinvey Business Logic, to iterate through an object, you should always look to use the async module.

Yea, it's true, I don't usually use loops to get multiple results... this was just a temporary quick solution while I was building a feature.



I haven't been developing on the business logic again after that day, but when I will do I'll check if anything similar happens on the log console and in case I'll provide more instances.



And, about async module, I've actually never looked well into it... the only times I needed to do async operations, I just used a "public" variable to keep track of whether there's still operations to wait for or not. I'll look better into it :)

Okay I developed again on BL today, and just tried to understand when was the problem happening.

I realized it's probably happening when an error occurs very shortly after the modules.logger.info has been called.

It seems like the error doesn't let enough time to the logger to run. But it's still a bit unclear when does that actually happen and when doesn't.

I'll post here some tests I've done and their results.



---



_logger.info("THE FIRST LINE WORKS FINE");

null.toString();

modules.collectionAccess.collection('TestCollection').find({}, function (err, docs) {

modules.logger.info("ALSO THE FIND METHOD WORKS FINE");

});



logs "THE FIRST LINE WORKS FINE"

and this is right, cause the error is before the "find" method is called.



---



_logger.info("THE FIRST LINE WORKS FINE");

modules.collectionAccess.collection('TestCollection').find({}, function (err, docs) {

modules.logger.info("ALSO THE FIND METHOD WORKS FINE");

null.toString();

});





logs "THE FIRST LINE WORKS FINE",

but not the second one...even tho technically the error is after the second logger.info call.



---



_logger.info("THE FIRST LINE WORKS FINE");

modules.collectionAccess.collection('TestCollection').find({}, function (err, docs) {

modules.logger.info("ALSO THE FIND METHOD WORKS FINE");

modules.collectionAccess.collection('TestCollection').find({}, function (err, docs) {

null.toString();

});

});



logs both "THE FIRST LINE WORKS FINE"

and "ALSO THE FIND METHOD WORKS FINE".

and this is right again, cause the error is only inside of the 2nd "find" method.





I think the problem comes in especially in situations like the 2nd example, where the "find" actually worked fine, called its callback...but the log doesn't show it.

That's interesting. Errors in callbacks have the (intentional) effect of killing the process that your code is running in. Logging statements are added to a queue to be processed, so it's possible that the process is killed prior to the log entry getting written to. I'll take a look and see if that's the case.

Hi @"Davide Neri"‌,



We've made a few changes in the last month to our BL processing logic which may have resolved this issue - is it still occurring?

Hey Michael

sorry haven't been working on back-end till now.

I just tried again the code snippets I posted before, and the 2nd one still isn't working well, logs only the first message but not the second one.



modules.logger.info("THIS MESSAGE IS LOGGED");

modules.collectionAccess.collection('Conversation').find({}, function (err, docs) {

modules.logger.info("BUT THIS ONE ISN'T...");

var i, j;

for(i=0; i
j = i*i;

modules.logger.info("...NOT EVEN IF I COUNT UP TO: " + i + " : ) ");

null.toString();

response.complete();

});