Querying data with query strings results unexpected data

[floufen]

Hi,

When provisioning an actuator using iotagent-ul, retrieving data with query string results to unexpected entities.

Here is how to reproduce this behavour :

$ git clone https://github.com/FIWARE/tutorials.IoT-over-MQTT
$ cd tutorials.IoT-over-MQTT
$ ./services start

Add service:

$ curl -iX POST \
  'http://localhost:4041/iot/services' \
  -H 'Content-Type: application/json' \
  -H 'fiware-service: openiot' \
  -H 'fiware-servicepath: /' \
  -d '{                            
 "services": [    
   {            
     "apikey":      "4jggokgpepnvsb2uv4s40d59ov",
     "cbroker":     "http://orion:1026",     
     "entity_type": "Thing",                       
     "resource":    ""                    
   }                                            
 ]                                  
}' 

and provision command :

$ curl -iX POST \
  'http://localhost:4041/iot/devices' \
  -H 'Content-Type: application/json' \
  -H 'fiware-service: openiot' \
  -H 'fiware-servicepath: /' \
  -d '{
  "devices": [
    {
      "device_id": "bell001",
      "entity_name": "urn:ngsi-ld:Bell:001",
      "entity_type": "Bell",
      "protocol": "PDI-IoTA-UltraLight",
      "transport": "MQTT",
      "commands": [
        { "name": "ring", "type": "command" }
       ]
    }
  ]
}
'

from now if retreive an entity with valid attribute it results to good result :

$ curl "http://localhost:1026/v2/entities/?q=ring_status=='UNKNOWN'&options=keyValues&type=Bell" -H 'fiware-service: openiot' -H 'fiware-servicepath: /'
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   135  100   135    0     0  12272      0 --:--:-- --:--:-- --:--:-- 12272
[
    {
        "TimeInstant": "2020-05-28T09:58:19.00Z",
        "id": "urn:ngsi-ld:Bell:001",
        "ring": "",
        "ring_info": " ",
        "ring_status": "UNKNOWN",
        "type": "Bell"
    }
]

but if the attributes doesn't exist or not equal it results this entity :

$ curl "http://localhost:1026/v2/entities/?q=ring_status=='UNKNsdsdN'&options=keyValues&type=Bell" -H 'fiware-service: openiot' -H 'fiware-servicepath: /'
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100    55  100    55    0     0   4583      0 --:--:-- --:--:-- --:--:--  4583
[
    {
        "id": "urn:ngsi-ld:Bell:001",
        "ring": "",
        "type": "Bell"
    }
]
 

$ curl "http://localhost:1026/v2/entities/?q=notexists=='anything'&options=keyValues&type=Bell" -H 'fiware-service: openiot' -H 'fiware-servicepath: /'
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100    55  100    55    0     0   4583      0 --:--:-- --:--:-- --:--:--  4583
[
    {
        "id": "urn:ngsi-ld:Bell:001",
        "ring": "",
        "type": "Bell"
    }
]
 

Why this behaviour ?

[fgalan]

To complete the picture we would need some extra information:

• The exact registration that IOTA does at CB. It can be obtained in the Orion database (registrations collection)
• The CB-IOTA interactions (request/response) that take place associated to each one of the GET /v2/entities operations shown above, either capturing on the wire (wireshark?) or in the logs (the following reference could help: https://fiware-orion.readthedocs.io/en/master/admin/management_api/index.html#tracelevel-related-with-inputoutput-payloads)

Thanks!

[floufen]

Here the registration of the orion-openiot database:

The exact registration that IOTA does at CB. It can be obtained in the Orion database (registrations collection)

> use orion-openiot
switched to db orion-openiot
> db["registrations"].find()
{ "_id" : ObjectId("5eddfc03e7e028b0e09312bb"), "expiration" : NumberLong("9223372036854775807"), "servicePath" : "/", "contextRegistration" : [ { "entities" : [ { "id" : "urn:ngsi-ld:Bell:001", "type" : "Bell" } ], "attrs" : [ { "name" : "ring", "type" : "" } ], "providingApplication" : "http://iot-agent:4041" } ], "format" : "normalized" }

The CB-IOTA interactions (request/response) that take place associated to each one of the GET /v2/entities operations shown above, either capturing on the wire (wireshark?) or in the logs (the following reference could help: https://fiware-orion.readthedocs.io/en/master/admin/management_api/index.html#tracelevel-related-with-inputoutput-payloads)

I didn't understand how to get the traces, but I retrieve the orion container's logs.
With a valid query I get :

curl "http://localhost:1026/v2/entities/?q=ring_status=='UNKNOWN'&options=keyValues&type=Bell" -H 'fiware-service: openiot' -H 'fiware-servicepath: /'
-------------------------
time=Monday 08 Jun 08:51:33 2020.141Z | lvl=INFO | corr=40c10dc8-a965-11ea-a71d-0242ac120104 | trans=1591606151-662-00000000017 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=logMsg.h[1844]:lmTransactionStart | msg=Starting transaction from 172.18.1.1:44940/v2
/entities/ 
time=Monday 08 Jun 08:51:33 2020.141Z | lvl=INFO | corr=40c10dc8-a965-11ea-a71d-0242ac120104 | trans=1591606151-662-00000000017 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=rest.cpp[874]:servicePathSplit | msg=Service Path 0: '/' 
time=Monday 08 Jun 08:51:33 2020.141Z | lvl=INFO | corr=40c10dc8-a965-11ea-a71d-0242ac120104 | trans=1591606151-662-00000000017 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=connectionOperations.cpp[182]:collectionRangedQuery | msg=Database Operation Successf
ul (query: { query: { _id.type: "Bell", _id.servicePath: "/", attrs.ring_status.value: { $eq: "UNKNOWN" } }, orderby: { creDate: 1 } }) 
time=Monday 08 Jun 08:51:33 2020.142Z | lvl=INFO | corr=40c10dc8-a965-11ea-a71d-0242ac120104 | trans=1591606151-662-00000000017 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=connectionOperations.cpp[182]:collectionRangedQuery | msg=Database Operation Successf
ul (query: { query: { $or: [ { contextRegistration.entities.id: /.*/, contextRegistration.entities.type: "Bell" }, { contextRegistration.entities.id: ".*", contextRegistration.entities.isPattern: "true", contextRegistration.entities.type: { $in: [ "Bell" ] } }, { contextReg
istration.entities.id: ".*", contextRegistration.entities.isPattern: "true", contextRegistration.entities.type: { $exists: false } } ], expiration: { $gt: 1591606293 }, servicePath: "/" }, orderby: { _id: 1 } }) 
time=Monday 08 Jun 08:51:33 2020.142Z | lvl=INFO | corr=40c10dc8-a965-11ea-a71d-0242ac120104 | trans=1591606151-662-00000000018 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=logMsg.h[1844]:lmTransactionStart | msg=Starting transaction to http://iot-agent:4041
//op/query 
time=Monday 08 Jun 08:51:33 2020.142Z | lvl=INFO | corr=40c10dc8-a965-11ea-a71d-0242ac120104 | trans=1591606151-662-00000000018 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=httpRequestSend.cpp[550]:httpRequestSendWithCurl | msg=Sending message 1 to HTTP serv
er: sending message of 333 bytes to HTTP server 
time=Monday 08 Jun 08:51:33 2020.154Z | lvl=INFO | corr=40c10dc8-a965-11ea-a71d-0242ac120104 | trans=1591606151-662-00000000018 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=httpRequestSend.cpp[570]:httpRequestSendWithCurl | msg=Notification Successfully Sent
 to http://iot-agent:4041//op/query 
time=Monday 08 Jun 08:51:33 2020.155Z | lvl=INFO | corr=40c10dc8-a965-11ea-a71d-0242ac120104 | trans=1591606151-662-00000000018 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=httpRequestSend.cpp[579]:httpRequestSendWithCurl | msg=Notification response OK, http
 code: 200 
time=Monday 08 Jun 08:51:33 2020.155Z | lvl=INFO | corr=40c10dc8-a965-11ea-a71d-0242ac120104 | trans=1591606151-662-00000000018 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=logMsg.h[1874]:lmTransactionEnd | msg=Transaction ended

And the logs with an invalid query :

curl "http://localhost:1026/v2/entities/?q=ring_status=='UNKNsdsdN'&options=keyValues&type=Bell" -H 'fiware-service: openiot' -H 'fiware-servicepath: /'
-----------------------------
time=Monday 08 Jun 08:52:33 2020.981Z | lvl=INFO | corr=65048476-a965-11ea-8c7c-0242ac120104 | trans=1591606151-662-00000000025 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=logMsg.h[1844]:lmTransactionStart | msg=Starting transaction from 172.18.1.1:44970/v2
/entities/ 
time=Monday 08 Jun 08:52:33 2020.981Z | lvl=INFO | corr=65048476-a965-11ea-8c7c-0242ac120104 | trans=1591606151-662-00000000025 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=rest.cpp[874]:servicePathSplit | msg=Service Path 0: '/' 
time=Monday 08 Jun 08:52:33 2020.981Z | lvl=INFO | corr=65048476-a965-11ea-8c7c-0242ac120104 | trans=1591606151-662-00000000025 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=connectionOperations.cpp[182]:collectionRangedQuery | msg=Database Operation Successf
ul (query: { query: { _id.type: "Bell", _id.servicePath: "/", attrs.ring_status.value: { $eq: "UNKNsdsdN" } }, orderby: { creDate: 1 } }) 
time=Monday 08 Jun 08:52:33 2020.982Z | lvl=INFO | corr=65048476-a965-11ea-8c7c-0242ac120104 | trans=1591606151-662-00000000025 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=connectionOperations.cpp[182]:collectionRangedQuery | msg=Database Operation Successf
ul (query: { query: { $or: [ { contextRegistration.entities.id: /.*/, contextRegistration.entities.type: "Bell" }, { contextRegistration.entities.id: ".*", contextRegistration.entities.isPattern: "true", contextRegistration.entities.type: { $in: [ "Bell" ] } }, { contextReg
istration.entities.id: ".*", contextRegistration.entities.isPattern: "true", contextRegistration.entities.type: { $exists: false } } ], expiration: { $gt: 1591606353 }, servicePath: "/" }, orderby: { _id: 1 } }) 
time=Monday 08 Jun 08:52:33 2020.982Z | lvl=INFO | corr=65048476-a965-11ea-8c7c-0242ac120104 | trans=1591606151-662-00000000025 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=connectionOperations.cpp[182]:collectionRangedQuery | msg=Database Operation Successf
ul (query: { query: { $or: [ { contextRegistration.entities.id: /.*/, contextRegistration.entities.type: "Bell" }, { contextRegistration.entities.id: ".*", contextRegistration.entities.isPattern: "true", contextRegistration.entities.type: { $in: [ "Bell" ] } }, { contextReg
istration.entities.id: ".*", contextRegistration.entities.isPattern: "true", contextRegistration.entities.type: { $exists: false } } ], expiration: { $gt: 1591606353 }, servicePath: "/" }, orderby: { _id: 1 } }) 
time=Monday 08 Jun 08:52:33 2020.982Z | lvl=INFO | corr=65048476-a965-11ea-8c7c-0242ac120104 | trans=1591606151-662-00000000026 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=logMsg.h[1844]:lmTransactionStart | msg=Starting transaction to http://iot-agent:4041
//op/query 
time=Monday 08 Jun 08:52:33 2020.982Z | lvl=INFO | corr=65048476-a965-11ea-8c7c-0242ac120104 | trans=1591606151-662-00000000026 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=httpRequestSend.cpp[550]:httpRequestSendWithCurl | msg=Sending message 4 to HTTP serv
er: sending message of 333 bytes to HTTP server 
time=Monday 08 Jun 08:52:33 2020.992Z | lvl=INFO | corr=65048476-a965-11ea-8c7c-0242ac120104 | trans=1591606151-662-00000000026 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=httpRequestSend.cpp[570]:httpRequestSendWithCurl | msg=Notification Successfully Sent
 to http://iot-agent:4041//op/query 
time=Monday 08 Jun 08:52:33 2020.992Z | lvl=INFO | corr=65048476-a965-11ea-8c7c-0242ac120104 | trans=1591606151-662-00000000026 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=httpRequestSend.cpp[579]:httpRequestSendWithCurl | msg=Notification response OK, http
 code: 200 
time=Monday 08 Jun 08:52:33 2020.993Z | lvl=INFO | corr=65048476-a965-11ea-8c7c-0242ac120104 | trans=1591606151-662-00000000026 | from=172.18.1.1 | srv=openiot | subsrv=/ | comp=Orion | op=logMsg.h[1874]:lmTransactionEnd | msg=Transaction ended

It looks like, when the service and service-path are set, orion will retrieve all registered entity.

[floufen]

The problem occurs with all registrations with leagacyFormat not set. So when the format is equal to "normalized", any invalid term will return an unexpected response. But if we force format to "JSON" (legacyFormat: true), the problem is solved.

To reproduce the problem you juste have to create a registration without legacyFormat set.

example:

curl -iX POST \
  'http://localhost:1026/v2/registrations' \
  -H 'Content-Type: application/json' \
  -d '{
  "description": "Name",
  "dataProvided": {
    "entities": [
      {
        "id": "urn:ngsi-ld:Store:001", "type": "Store"
      }
    ],
    "attrs": ["name"]
  },
  "provider": {
    "http": {"url": "http://orion:1026/v2"}
  }
}'

curl "http://localhost:1026/v2/entities/?q=name~=Ei&options=keyValues&type=Store"
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   271  100   271    0     0   5645      0 --:--:-- --:--:-- --:--:--  5645
[
    {
        "address": {
            "addressLocality": "Prenzlauer Berg",
            "addressRegion": "Berlin",
            "postalCode": "10439",
            "streetAddress": "Bornholmer Stra\u00dfe 65"
        },
        "id": "urn:ngsi-ld:Store:001",
        "location": {
            "coordinates": [
                13.3986,
                52.5547
            ],
            "type": "Point"
        },
        "name": "B\u00f6sebr\u00fccke Einkauf",
        "type": "Store"
    }
]

with a nonexistent term it gives :

curl "http://localhost:1026/v2/entities/?q=name~=DOESNOTEXISTS&options=keyValues&type=Store"
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100    77  100    77    0     0    262      0 --:--:-- --:--:-- --:--:--   261
[
    {
        "id": "urn:ngsi-ld:Store:001",
        "name": "B\u00f6sebr\u00fccke Einkauf",
        "type": "Store"
    }
]

If I create a registration with legacyFormat to true or if I modify the format attribute to JSON in registrations collection in mongo, querying with an invalid term will gives a valid result:

curl "http://localhost:1026/v2/entities/?q=name~=dEi&options=keyValues&type=Store"
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100     2  100     2    0     0     47      0 --:--:-- --:--:-- --:--:--    47
[]

[fgalan]

Thank you for so detailed report! I'll have a look when I some time and provide feedback

[fgalan]

If I create a registration with legacyFormat to true or if I modify the format attribute to JSON in registrations collection in mongo...

Do you only modify the format (either directly in MongoDB collection or indirectly by re-creating the registration)? Or do you also modify the provider URL (shown as http://orion:1026/v2 in your example above)?

[fgalan]

I'd like to share the results of some testing I have been doing.

I have two instances of Orion, one running on port 1026 acting as Context Broker, the other running in port 1027 acting as context provider (CPr). I use the following to run them:

contextBroker -fg -port 1026 -db orion
contextBroker -fg -port 1027 -db orion-cpr -pidpath /tmp/context.cpr

I create an entity in the context provider with the following request:

curl -iX POST \
  'http://localhost:1027/v2/entities' \
  -H 'Content-Type: application/json' \
  -d '{
  "id": "urn:ngsi-ld:Store:001",
  "type": "Store",
  "name": {"value": "Entity name for testing", "type": "Text" }
}'

So, setup ready, let's start to test...

---

First test is using a registration with legacy format. I create the registration using the following request. Note the URL uses /v1 (otherwise the queryContext operation Context Broker does will use an invalid path and will end in a "not service found" error).

curl -iX POST \
  'http://localhost:1026/v2/registrations' \
  -H 'Content-Type: application/json' \
  -d '{
  "description": "Name",
  "dataProvided": {
    "entities": [
      {
        "id": "urn:ngsi-ld:Store:001", "type": "Store"
      }
    ],
    "attrs": ["name"]
  },
  "provider": {
    "http": {"url": "http://localhost:1027/v1"},
	"legacyForwarding": true
  }
}'

Next, I do a request on Context Broker with valid name (OK):

curl "http://localhost:1026/v2/entities/?q=name~=for&options=keyValues&type=Store"

[{"id":"urn:ngsi-ld:Store:001","type":"Store","name":"Entity name for testing"}]

Next, I do a request on Context Broker with an invalid name (NOK):

curl "http://localhost:1026/v2/entities/?q=name~=UNKNOWN&options=keyValues&type=Store"

[{"id":"urn:ngsi-ld:Store:001","type":"Store","name":"Entity name for testing"}]

---

After deleting the registration of the past test, I create a new one without legacy format, using the following request. Note the URL now uses /v2 (otherwise the op/query operation Context Broker does will use an invalid path and will end in a "not service found" error).

curl -iX POST \
  'http://localhost:1026/v2/registrations' \
  -H 'Content-Type: application/json' \
  -d '{
  "description": "Name",
  "dataProvided": {
    "entities": [
      {
        "id": "urn:ngsi-ld:Store:001", "type": "Store"
      }
    ],
    "attrs": ["name"]
  },
  "provider": {
    "http": {"url": "http://localhost:1027/v2"}
  }
}'

Next, I do a request on Context Broker with valid name (OK):

curl "http://localhost:1026/v2/entities/?q=name~=for&options=keyValues&type=Store"

[{"id":"urn:ngsi-ld:Store:001","type":"Store","name":"Entity name for testing"}]

Next, I do a request on Context Broker with an invalid name (NOK)

curl "http://localhost:1026/v2/entities/?q=name~=UNKNOWN&options=keyValues&type=Store"

[{"id":"urn:ngsi-ld:Store:001","type":"Store","name":"Entity name for testing"}]

---

Conclusion: I think the problem is not related to the usage of legacyForwarding format, as it happens in both cases (either using legacyFormat true or not). This is weird, as report at #3657 (comment) tells otherwise. Some of us (@floufen or me) has some flaw in his testing process :)

[floufen]

If I create a registration with legacyFormat to true or if I modify the format attribute to JSON in registrations collection in mongo...

Thank you for the report !

Do you only modify the format (either directly in MongoDB collection or indirectly by re-creating the registration)? Or do you also modify the provider URL (shown as http://orion:1026/v2 in your example above)?

I just modified the format. The URL stays the same. My bad, I didn't notice the "not service found" error was thrown. It is not related to the usage of legacyForwarding.

The problem still exist. Can you tell me why the registrations database is searched while querying context broker data ? :)

[fgalan]

Let me start for the end :)

Can you tell me why the registrations database is searched while querying context broker data ? :)

It is searched in order to find Context Providers that could have information about the entity/attribute being queried. Orion does a "merge" on local information and Context Providers registrations.

For instance, you could have this situation:

• Orion has local information (entities collection) for attribute A in entity E
• Orion has a registration (registrations collection) for attribute B in entity E, pointing to URL1

A client does a query for entity E (e.g. GET /v2/entities/E). Thus, Orion checks two collections: entities (to find A value directly) and registrations (to find context providers URL1 for attribute B).

There are different kinds of queries and some ugly corner cases, but, basically, this is the way it is works.

[floufen]

Thank you for the explanation.
Why are queries not applied when extracting entities in the registrations collection? is it meant to be like that ?
I tested by doing some tweaking to the MongoGlobal.(cpp|h) to apply the queries and it seems that it resolves the issue.
Can you review the code please ? master...floufen:hotfix/queryfilter-registrations

[fgalan]

Why are queries not applied when extracting entities in the registrations collection? is it meant to be like that ?

Sorry, I don't understand what you mean. Could you elaborate a little bit, please?

I tested by doing some tweaking to the MongoGlobal.(cpp|h) to apply the queries and it seems that it resolves the issue.
Can you review the code please ? master...floufen:hotfix/queryfilter-registrations

Thanks for sharing your code modification. As far as I understand, you are applying filtering to the DB query done in registration collection in order to find candidate context providers to forward the client NGSI query. However, note that in that registrations collection you only have entities ids and types and attribute names and types, you don't have attribute values so filters like temperature>20 or geo-queries cannot be evaluated there.

But if you say is solving your issue maybe I'm missing something :) What would be useful at this point is to create a functional test case (i.e. a .test file to be used with testHarness.sh) covering your case. That .test should pass with your code and fail with current master. Could you provide that .test, please?

[floufen]

Hahah I am sorry. I did the modifications without understanding how the code really works and how the datas are stored. It seemed to work because all the the registrations were filtered.
Now I did understand that the query filtering is not, yet, supported on query forwarding.
I close this issue because it's a duplicate of #2282