from=, corr=, srv= and subsrv= are not correctly propagated in transactions corresponding to notifications triggered by updates in log traces

[fgalan]

Let's consider the following situation: 1 entity with 1 subscription associated, in a given service and subservice (e.g. "foo" and "/far). Orion is running with log level INFO. An update on the entity is done, generating a notification. This involves the following log traces:

time=Friday 12 Jan 13:24:17 2018.374Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1832]:lmTransactionStart | msg=Starting transaction from 0.0.0.0:41930/v2/entities/E1/attrs/A
time=Friday 12 Jan 13:24:17 2018.374Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=pending | subsrv=/bar | comp=Orion | op=rest.cpp[881]:servicePathSplit | msg=Service Path 0: '/bar'
time=Friday 12 Jan 13:24:17 2018.375Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=foo | subsrv=/bar | comp=Orion | op=connectionOperations.cpp[237]:collectionCount | msg=Database Operation Successful (count: { _id.id: "E1", _id.servicePath: { $in: [ /^/bar$/ ] } })
time=Friday 12 Jan 13:24:17 2018.375Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=foo | subsrv=/bar | comp=Orion | op=connectionOperations.cpp[92]:collectionQuery | msg=Database Operation Successful (query: { _id.id: "E1", _id.servicePath: { $in: [ /^/bar$/ ] } })
time=Friday 12 Jan 13:24:17 2018.460Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=foo | subsrv=/bar | comp=Orion | op=connectionOperations.cpp[92]:collectionQuery | msg=Database Operation Successful (query: { $or: [ { entities.id: "E1", $or: [ { entities.type: "T" }, { entities.type: { $exists: false } } ], entities.isPattern: "false", entities.isTypePattern: { $ne: true }, expiration: { $gt: 1515763457 }, status: { $ne: "inactive" }, servicePath: { $in: [ /^$|^/#$|^/bar/#$|^/bar$/, null ] } }, { entities.isPattern: "true", entities.isTypePattern: { $ne: true }, expiration: { $gt: 1515763457 }, status: { $ne: "inactive" }, servicePath: { $in: [ /^$|^/#$|^/bar/#$|^/bar$/, null ] }, $where: function(){for (var i=0; i < this.entities.length; i++) {if (this.enti... }, { entities.isPattern: "false", entities.isTypePattern: true, expiration: { $gt: 1515763457 }, status: { $ne: "inactive" }, servicePath: { $in: [ /^$|^/#$|^/bar/#$|^/bar$/, null ] }, $where: function(){for (var i=0; i < this.entities.length; i++) {if (this.enti... }, { entities.isPattern: "true", entities.isTypePattern: true, expiration: { $gt: 1515763457 }, status: { $ne: "inactive" }, servicePath: { $in: [ /^$|^/#$|^/bar/#$|^/bar$/, null ] }, $where: function(){for (var i=0; i < this.entities.length; i++) {if (this.enti... } ] })
time=Friday 12 Jan 13:24:17 2018.460Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=foo | subsrv=/bar | comp=Orion | op=connectionOperations.cpp[447]:collectionUpdate | msg=Database Operation Successful (update: <{ _id.id: "E1", _id.type: "T", _id.servicePath: { $in: [ /^/bar$/ ] } }, { $set: { attrs.A: { value: 29782.0, type: "Number", mdNames: [], creDate: 1515763429, modDate: 1515763457 }, modDate: 1515763457, lastCorrelator: "e3e86aba-f79b-11e7-8622-000c29173617" }, $unset: { location: 1 } }>)
time=Friday 12 Jan 13:24:17 2018.461Z | lvl=INFO | corr=N/A | trans=1515763366-150-00000000007 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1832]:lmTransactionStart | msg=Starting transaction to http://localhost:1028/accumulate
time=Friday 12 Jan 13:24:17 2018.461Z | lvl=INFO | corr=N/A | trans=1515763366-150-00000000007 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=httpRequestSend.cpp[592]:httpRequestSendWithCurl | msg=Sending message 3 to HTTP server: sending message of 409 bytes to HTTP server
time=Friday 12 Jan 13:24:17 2018.461Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=foo | subsrv=/bar | comp=Orion | op=connectionOperations.cpp[447]:collectionUpdate | msg=Database Operation Successful (update: <{ _id: ObjectId('5a58b6aa22062545d52f1bb2') }, { $set: { lastNotification: 1515763457 }, $inc: { count: 1 } }>)
time=Friday 12 Jan 13:24:17 2018.461Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=foo | subsrv=/bar | comp=Orion | op=logMsg.h[1916]:lmTransactionEnd | msg=Transaction ended
time=Friday 12 Jan 13:24:17 2018.469Z | lvl=INFO | corr=N/A | trans=1515763366-150-00000000007 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=httpRequestSend.cpp[613]:httpRequestSendWithCurl | msg=Notification Successfully Sent to http://localhost:1028/accumulate
time=Friday 12 Jan 13:24:17 2018.469Z | lvl=INFO | corr=N/A | trans=1515763366-150-00000000007 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1916]:lmTransactionEnd | msg=Transaction ended
time=Friday 12 Jan 13:24:17 2018.470Z | lvl=INFO | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=connectionOperations.cpp[447]:collectionUpdate | msg=Database Operation Successful (update: <{ _id: ObjectId('5a58b6aa22062545d52f1bb2'), $or: [ { lastNotification: { $lt: 1515763457 } }, { lastNotification: { $exists: false } } ] }, { $set: { lastNotification: 1515763457 } }>)
time=Friday 12 Jan 13:24:17 2018.470Z | lvl=INFO | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=connectionOperations.cpp[447]:collectionUpdate | msg=Database Operation Successful (update: <{ _id: ObjectId('5a58b6aa22062545d52f1bb2'), $or: [ { lastSuccess: { $lt: 1515763457 } }, { lastSuccess: { $exists: false } } ] }, { $set: { lastSuccess: 1515763457 } }>)

trasn= ended in 6 corresponds to the update and transaction 7 to the notification. Note that in that one corr= is N/A and the others (srv=, subsrv= and from=) are "pending" instead of having the same values than transaction 6 used.

Some additional findings:

• The problem seems to be independent of the -notificatonMode. At least it occurs in the transient and threadpool cases.
• The problem only affects to the logs system. The Fiware-Service, Fiware-ServicePath and Fiware-Correlator headers uses the correct values, propagated from the update.

Also related wit this (but minor) are the two messages at the bottom, using N/A for the four fields. Actually they are related with the notification transaction, but probably are using N/A as they are functions in the cache management logic. Have a look to this also, in the case it has an easy fix.

[fgalan]

Useful scripts to debug this:

contextBroker -fg -multiservice -logLevel INFO -noCache -notificationMode transient

contextBroker -fg -multiservice -logLevel INFO -noCache -notificationMode threadpool:50:5


curl -v localhost:1026/v2/subscriptions -s -S -H 'Content-Type: application/json' -H 'Fiware-Service: foo' -H 'Fiware-ServicePath: /bar' -d @- <<EOF
{
  "description": "A subscription to get info about Room1",
  "subject": {
    "entities": [
      {
        "id": "E1",
        "type": "T"
      }
    ],
    "condition": {
      "attrs": [
        "A"
      ]
    }
  },
  "notification": {
    "http": {
      "url": "http://localhost:1028/accumulate"
    }
  }
}
EOF

curl localhost:1026/v2/entities -s -S -H 'Content-Type: application/json' -H 'Fiware-Service: foo' -H 'Fiware-ServicePath: /bar' -d @- <<EOF
{
  "id": "E1",
  "type": "T",
  "A": {
    "value": $RANDOM,
    "type": "Number"
  }
}
EOF

curl -X PUT localhost:1026/v2/entities/E1/attrs/A -s -S -H 'Content-Type: application/json' -H 'Fiware-Service: foo' -H 'Fiware-ServicePath: /bar' -d @- <<EOF
{
  "value": $RANDOM,
  "type": "Number" 
}
EOF

[fgalan]

Fixed by PR #3414.

Let's compare the one in this issue with the problem (top):

time=Friday 12 Jan 13:24:17 2018.374Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1832]:lmTransactionStart | msg=Starting transaction from 0.0.0.0:41930/v2/entities/E1/attrs/A
time=Friday 12 Jan 13:24:17 2018.374Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=pending | subsrv=/bar | comp=Orion | op=rest.cpp[881]:servicePathSplit | msg=Service Path 0: '/bar'
time=Friday 12 Jan 13:24:17 2018.375Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=foo | subsrv=/bar | comp=Orion | op=connectionOperations.cpp[237]:collectionCount | msg=Database Operation Successful (count: { _id.id: "E1", _id.servicePath: { $in: [ /^/bar$/ ] } })
time=Friday 12 Jan 13:24:17 2018.375Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=foo | subsrv=/bar | comp=Orion | op=connectionOperations.cpp[92]:collectionQuery | msg=Database Operation Successful (query: { _id.id: "E1", _id.servicePath: { $in: [ /^/bar$/ ] } })
time=Friday 12 Jan 13:24:17 2018.460Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=foo | subsrv=/bar | comp=Orion | op=connectionOperations.cpp[92]:collectionQuery | msg=Database Operation Successful (query: { $or: [ { entities.id: "E1", $or: [ { entities.type: "T" }, { entities.type: { $exists: false } } ], entities.isPattern: "false", entities.isTypePattern: { $ne: true }, expiration: { $gt: 1515763457 }, status: { $ne: "inactive" }, servicePath: { $in: [ /^$|^/#$|^/bar/#$|^/bar$/, null ] } }, { entities.isPattern: "true", entities.isTypePattern: { $ne: true }, expiration: { $gt: 1515763457 }, status: { $ne: "inactive" }, servicePath: { $in: [ /^$|^/#$|^/bar/#$|^/bar$/, null ] }, $where: function(){for (var i=0; i < this.entities.length; i++) {if (this.enti... }, { entities.isPattern: "false", entities.isTypePattern: true, expiration: { $gt: 1515763457 }, status: { $ne: "inactive" }, servicePath: { $in: [ /^$|^/#$|^/bar/#$|^/bar$/, null ] }, $where: function(){for (var i=0; i < this.entities.length; i++) {if (this.enti... }, { entities.isPattern: "true", entities.isTypePattern: true, expiration: { $gt: 1515763457 }, status: { $ne: "inactive" }, servicePath: { $in: [ /^$|^/#$|^/bar/#$|^/bar$/, null ] }, $where: function(){for (var i=0; i < this.entities.length; i++) {if (this.enti... } ] })
time=Friday 12 Jan 13:24:17 2018.460Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=foo | subsrv=/bar | comp=Orion | op=connectionOperations.cpp[447]:collectionUpdate | msg=Database Operation Successful (update: <{ _id.id: "E1", _id.type: "T", _id.servicePath: { $in: [ /^/bar$/ ] } }, { $set: { attrs.A: { value: 29782.0, type: "Number", mdNames: [], creDate: 1515763429, modDate: 1515763457 }, modDate: 1515763457, lastCorrelator: "e3e86aba-f79b-11e7-8622-000c29173617" }, $unset: { location: 1 } }>)
time=Friday 12 Jan 13:24:17 2018.461Z | lvl=INFO | corr=N/A | trans=1515763366-150-00000000007 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1832]:lmTransactionStart | msg=Starting transaction to http://localhost:1028/accumulate
time=Friday 12 Jan 13:24:17 2018.461Z | lvl=INFO | corr=N/A | trans=1515763366-150-00000000007 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=httpRequestSend.cpp[592]:httpRequestSendWithCurl | msg=Sending message 3 to HTTP server: sending message of 409 bytes to HTTP server
time=Friday 12 Jan 13:24:17 2018.461Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=foo | subsrv=/bar | comp=Orion | op=connectionOperations.cpp[447]:collectionUpdate | msg=Database Operation Successful (update: <{ _id: ObjectId('5a58b6aa22062545d52f1bb2') }, { $set: { lastNotification: 1515763457 }, $inc: { count: 1 } }>)
time=Friday 12 Jan 13:24:17 2018.461Z | lvl=INFO | corr=e3e86aba-f79b-11e7-8622-000c29173617 | trans=1515763366-150-00000000006 | from=0.0.0.0 | srv=foo | subsrv=/bar | comp=Orion | op=logMsg.h[1916]:lmTransactionEnd | msg=Transaction ended
time=Friday 12 Jan 13:24:17 2018.469Z | lvl=INFO | corr=N/A | trans=1515763366-150-00000000007 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=httpRequestSend.cpp[613]:httpRequestSendWithCurl | msg=Notification Successfully Sent to http://localhost:1028/accumulate
time=Friday 12 Jan 13:24:17 2018.469Z | lvl=INFO | corr=N/A | trans=1515763366-150-00000000007 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1916]:lmTransactionEnd | msg=Transaction ended
time=Friday 12 Jan 13:24:17 2018.470Z | lvl=INFO | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=connectionOperations.cpp[447]:collectionUpdate | msg=Database Operation Successful (update: <{ _id: ObjectId('5a58b6aa22062545d52f1bb2'), $or: [ { lastNotification: { $lt: 1515763457 } }, { lastNotification: { $exists: false } } ] }, { $set: { lastNotification: 1515763457 } }>)
time=Friday 12 Jan 13:24:17 2018.470Z | lvl=INFO | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=connectionOperations.cpp[447]:collectionUpdate | msg=Database Operation Successful (update: <{ _id: ObjectId('5a58b6aa22062545d52f1bb2'), $or: [ { lastSuccess: { $lt: 1515763457 } }, { lastSuccess: { $exists: false } } ] }, { $set: { lastSuccess: 1515763457 } }>)

with the one in the PR's branch:

time=Tuesday 29 Jan 18:02:38 2019.197Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000001 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1841]:lmTransactionStart | msg=Starting transaction from 0.0.0.0:44540/v2/entities/Room1/attrs
time=Tuesday 29 Jan 18:02:38 2019.197Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000001 | from=0.0.0.0 | srv=pending | subsrv=/BBB | comp=Orion | op=rest.cpp[885]:servicePathSplit | msg=Service Path 0: '/BBB'
time=Tuesday 29 Jan 18:02:38 2019.202Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000001 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=connectionOperations.cpp[239]:collectionCount | msg=Database Operation Successful (count: { _id.id: "Room1", _id.servicePath: { $in: [ /^/BBB$/ ] } })
time=Tuesday 29 Jan 18:02:38 2019.204Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000001 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=connectionOperations.cpp[94]:collectionQuery | msg=Database Operation Successful (query: { _id.id: "Room1", _id.servicePath: { $in: [ /^/BBB$/ ] } })
time=Tuesday 29 Jan 18:02:38 2019.311Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000001 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=connectionOperations.cpp[94]:collectionQuery | msg=Database Operation Successful (query: { $or: [ { entities.id: "Room1", $or: [ { entities.type: "Room" }, { entities.type: { $exists: false } } ], entities.isPattern: "false", entities.isTypePattern: { $ne: true }, expiration: { $gt: 1548784958 }, status: { $ne: "inactive" }, servicePath: { $in: [ /^$|^/#$|^/BBB/#$|^/BBB$/, null ] } }, { entities.isPattern: "true", entities.isTypePattern: { $ne: true }, expiration: { $gt: 1548784958 }, status: { $ne: "inactive" }, servicePath: { $in: [ /^$|^/#$|^/BBB/#$|^/BBB$/, null ] }, $where: function(){for (var i=0; i < this.entities.length; i++) {if (this.enti... }, { entities.isPattern: "false", entities.isTypePattern: true, expiration: { $gt: 1548784958 }, status: { $ne: "inactive" }, servicePath: { $in: [ /^$|^/#$|^/BBB/#$|^/BBB$/, null ] }, $where: function(){for (var i=0; i < this.entities.length; i++) {if (this.enti... }, { entities.isPattern: "true", entities.isTypePattern: true, expiration: { $gt: 1548784958 }, status: { $ne: "inactive" }, servicePath: { $in: [ /^$|^/#$|^/BBB/#$|^/BBB$/, null ] }, $where: function(){for (var i=0; i < this.entities.length; i++) {if (this.enti... } ] })
time=Tuesday 29 Jan 18:02:38 2019.312Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000001 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=connectionOperations.cpp[449]:collectionUpdate | msg=Database Operation Successful (update: <{ _id.id: "Room1", _id.type: "Room", _id.servicePath: { $in: [ /^/BBB$/ ] } }, { $set: { attrs.temperature: { value: 2332.0, type: "Float", mdNames: [], creDate: 1548780066, modDate: 1548784958 }, attrs.pressure: { value: 2332.0, type: "Float", mdNames: [], creDate: 1548780066, modDate: 1548784958 }, modDate: 1548784958, lastCorrelator: "102c35b2-23f0-11e9-9b1f-000c29173617" }, $unset: { location: 1, expDate: 1 } }>)
time=Tuesday 29 Jan 18:02:38 2019.312Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000002 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=logMsg.h[1841]:lmTransactionStart | msg=Starting transaction to http://localhost:1028/accumulate
time=Tuesday 29 Jan 18:02:38 2019.312Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000001 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=connectionOperations.cpp[307]:collectionFindOne | msg=Database Operation Successful (findOne: { _id: ObjectId('5c5081b5bd0bb0c9841da3af') })
time=Tuesday 29 Jan 18:02:38 2019.312Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000002 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=httpRequestSend.cpp[592]:httpRequestSendWithCurl | msg=Sending message 1 to HTTP server: sending message of 429 bytes to HTTP server
time=Tuesday 29 Jan 18:02:38 2019.313Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000001 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=connectionOperations.cpp[449]:collectionUpdate | msg=Database Operation Successful (update: <{ _id: ObjectId('5c5081b5bd0bb0c9841da3af') }, { $set: { lastNotification: 1548784958 }, $inc: { count: 1 } }>)
time=Tuesday 29 Jan 18:02:38 2019.313Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000001 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=logMsg.h[1925]:lmTransactionEnd | msg=Transaction ended
time=Tuesday 29 Jan 18:02:38 2019.322Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000002 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=httpRequestSend.cpp[613]:httpRequestSendWithCurl | msg=Notification Successfully Sent to http://localhost:1028/accumulate
time=Tuesday 29 Jan 18:02:38 2019.323Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000002 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=connectionOperations.cpp[449]:collectionUpdate | msg=Database Operation Successful (update: <{ _id: ObjectId('5c5081b5bd0bb0c9841da3af'), $or: [ { lastNotification: { $lt: 1548784958 } }, { lastNotification: { $exists: false } } ] }, { $set: { lastNotification: 1548784958 } }>)
time=Tuesday 29 Jan 18:02:38 2019.324Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000002 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=connectionOperations.cpp[449]:collectionUpdate | msg=Database Operation Successful (update: <{ _id: ObjectId('5c5081b5bd0bb0c9841da3af'), $or: [ { lastSuccess: { $lt: 1548784958 } }, { lastSuccess: { $exists: false } } ] }, { $set: { lastSuccess: 1548784958 } }>)
time=Tuesday 29 Jan 18:02:38 2019.324Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000002 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=logMsg.h[1925]:lmTransactionEnd | msg=Transaction ended

All using the same corr/srv/subsrv/from, two transactions (0001 for the update, 0002 for the notification sent).

Check with all notification modes (permanent, transient an threadpool) in both cache and no-cache modes (i.e. the six possible combinations) and works fine.

[mrutid]

[srv=pending | subsrv=/BBB] Don't you know the srv at this point? there is any difference with subsrv?

[fgalan]

Yes, the first two ones are weird with regards srv= and subsrv=

time=Tuesday 29 Jan 18:02:38 2019.197Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000001 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=logMsg.h[1841]:lmTransactionStart | msg=Starting transaction from 0.0.0.0:44540/v2/entities/Room1/attrs
time=Tuesday 29 Jan 18:02:38 2019.197Z | lvl=INFO | corr=102c35b2-23f0-11e9-9b1f-000c29173617 | trans=1548784915-756-00000000001 | from=0.0.0.0 | srv=pending | subsrv=/BBB | comp=Orion | op=rest.cpp[885]:servicePathSplit | msg=Service Path 0: '/BBB'

I think it's easy to improve. I'll do:

[fgalan]

PR modified and now it looks like:

time=Wednesday 30 Jan 12:12:44 2019.846Z | lvl=INFO | corr=5992cbba-2488-11e9-9cdf-000c29173617 | trans=1548850360-467-00000000001 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=logMsg.h[1841]:lmTransactionStart | msg=Starting transaction from 0.0.0.0:39269/v2/entities
time=Wednesday 30 Jan 12:12:44 2019.846Z | lvl=INFO | corr=5992cbba-2488-11e9-9cdf-000c29173617 | trans=1548850360-467-00000000001 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=rest.cpp[885]:servicePathSplit | msg=Service Path 0: '/BBB'
time=Wednesday 30 Jan 12:12:44 2019.847Z | lvl=INFO | corr=5992cbba-2488-11e9-9cdf-000c29173617 | trans=1548850360-467-00000000001 | from=0.0.0.0 | srv=aaa | subsrv=/BBB | comp=Orion | op=connectionOperations.cpp[239]:collectionCount | msg=Database Operation Successful (count: { _id.id: "EUnknownName", _id.type: "T", _id.servicePath: { $in: [ /^/BBB$/ ] } })
---