transaction end moved up one level

[kzangeli]

Description

transaction end moved up one level, and all those "lower level invocations" have been removed.

Solves #478

[fgalan]

I have done the following test with bug/478_transaction_up_level branch.

Create one entity (Room1), create 3 subscriptions ONCHANGE on that entity. Then, do an update an get the following log trace:

time=2014-07-29T20:09:49.737CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=connectionTreat | comp=Orion | msg=rest.cpp[629]: Starting transaction from 0.0.0.0:37208/NGSI10/updateContext
time=2014-07-29T20:09:49.741CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=processContextElement | comp=Orion | msg=MongoCommonUpdate.cpp[1499]: Database Operation Successful ({ _id.id: "Room1", _id.type: "Room", _id.servicePath: { $exists: false } })
time=2014-07-29T20:09:49.742CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=addTriggeredSubscriptions | comp=Orion | msg=MongoCommonUpdate.cpp[811]: Database Operation Successful ({ $or: [ { entities.id: "Room1", $or: [ { entities.type: "Room" }, { entities.type: { $exists: false } } ], entities.isPattern: "false", conditions.type: "ONCHANGE", conditions.value: "temperature", expiration: { $gt: 1406657389 } }, { entities.isPattern: "true", conditions.type: "ONCHANGE", conditions.value: "temperature", expiration: { $gt: 1406657389 }, $where: function(){for (var i=0; i < this.entities.length; i++) {if (this.enti... } ] })
time=2014-07-29T20:09:49.742CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=addTriggeredSubscriptions | comp=Orion | msg=MongoCommonUpdate.cpp[811]: Database Operation Successful ({ $or: [ { entities.id: "Room1", $or: [ { entities.type: "Room" }, { entities.type: { $exists: false } } ], entities.isPattern: "false", conditions.type: "ONCHANGE", conditions.value: "pressure", expiration: { $gt: 1406657389 } }, { entities.isPattern: "true", conditions.type: "ONCHANGE", conditions.value: "pressure", expiration: { $gt: 1406657389 }, $where: function(){for (var i=0; i < this.entities.length; i++) {if (this.enti... } ] })
time=2014-07-29T20:09:49.742CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=processContextElement | comp=Orion | msg=MongoCommonUpdate.cpp[1644]: Database Operation Successful (update { _id.id: "Room1", _id.type: "Room", _id.servicePath: { $exists: false } })
time=2014-07-29T20:09:49.742CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=processSubscriptions | comp=Orion | msg=MongoCommonUpdate.cpp[874]: Database Operation Successful (findOne 53d7e31b47ab05f63d64319a)
time=2014-07-29T20:09:49.743CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=entitiesQuery | comp=Orion | msg=MongoGlobal.cpp[881]: Database Operation Successful ({ query: { $or: [ { _id.id: "Room1", _id.type: "Room" } ], _id.servicePath: { $exists: false }, attrs.name: { $in: [ "temperature" ] } }, orderby: { creDate: 1 } })
time=2014-07-29T20:09:49.743CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=processSubscriptions | comp=Orion | msg=MongoCommonUpdate.cpp[926]: Database Operation Successful (update: { $set: { lastNotification: 1406657389 }, $inc: { count: 1 } }, query: { _id: ObjectId('53d7e31b47ab05f63d64319a') })
time=2014-07-29T20:09:49.743CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=processSubscriptions | comp=Orion | msg=MongoCommonUpdate.cpp[874]: Database Operation Successful (findOne 53d7e32447ab05f63d64319b)
time=2014-07-29T20:09:49.743CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=entitiesQuery | comp=Orion | msg=MongoGlobal.cpp[881]: Database Operation Successful ({ query: { $or: [ { _id.id: "Room1", _id.type: "Room" } ], _id.servicePath: { $exists: false }, attrs.name: { $in: [ "temperature" ] } }, orderby: { creDate: 1 } })
time=2014-07-29T20:09:49.744CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=processSubscriptions | comp=Orion | msg=MongoCommonUpdate.cpp[926]: Database Operation Successful (update: { $set: { lastNotification: 1406657389 }, $inc: { count: 1 } }, query: { _id: ObjectId('53d7e32447ab05f63d64319b') })
time=2014-07-29T20:09:49.744CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=processSubscriptions | comp=Orion | msg=MongoCommonUpdate.cpp[874]: Database Operation Successful (findOne 53d7e33247ab05f63d64319c)
time=2014-07-29T20:09:49.744CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=entitiesQuery | comp=Orion | msg=MongoGlobal.cpp[881]: Database Operation Successful ({ query: { $or: [ { _id.id: "Room1", _id.type: "Room" } ], _id.servicePath: { $exists: false }, attrs.name: { $in: [ "temperature" ] } }, orderby: { creDate: 1 } })
time=2014-07-29T20:09:49.744CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=processSubscriptions | comp=Orion | msg=MongoCommonUpdate.cpp[926]: Database Operation Successful (update: { $set: { lastNotification: 1406657389 }, $inc: { count: 1 } }, query: { _id: ObjectId('53d7e33247ab05f63d64319c') })
time=2014-07-29T20:09:49.744CEST | lvl=WARNING | trans=1406657233-130-00000000005 | function=sendHttpSocket | comp=Orion | msg=clientSocketHttp.cpp[286]: Notification failure for localhost:1028 (curl_easy_perform failed: Couldn't connect to server)
time=2014-07-29T20:09:49.748CEST | lvl=INFO | trans=1406657233-130-00000000005 | function=requestCompleted | comp=Orion | msg=rest.cpp[370]: Transaction ended
time=2014-07-29T20:09:49.748CEST | lvl=WARNING | trans=1406657233-130-00000000005 | function=sendHttpSocket | comp=Orion | msg=clientSocketHttp.cpp[286]: Notification failure for localhost:1028 (curl_easy_perform failed: Couldn't connect to server)
time=2014-07-29T20:09:49.749CEST | lvl=WARNING | trans=1406657233-130-00000000005 | function=sendHttpSocket | comp=Orion | msg=clientSocketHttp.cpp[286]: Notification failure for localhost:1028 (curl_easy_perform failed: Couldn't connect to server)

The notification failure message is normal (given that I've run the test without setting proper receptors). However, what is weird are the two messages associated to trans 1406657233-130-00000000005 after the "Transaction ended" message.

The problem seems to be difficult to solve with the current approach, given that notification and updateContext procesing live (where I guess the transaction end message is printed) in different threads.

Alternatives:

1. Leave it as it is now, assuming it is a normal behaviour (I don't like it: the system processing the log may get crazy)
2. Implement some kind of "join thread" mechanism, so transaction end printing is deferred until all notification threads have ended (how difficult it is?)
3. Consider that each notification sent due to ONCHANGE correspondt to a different transaction (I think that for ONTIMEINTERVAL this is the way it works and we don't need extra changes).

Except if 2 is easy, I'll suggest going for 3. Not sure if for 0.14.1 (we are running out of time) or for the next release (assuming this as a bug to be solved in 0.14.1_next).