Notification problems after a while #1390

Jxlle · 2023-06-19T18:53:58Z

For my use-case I use a lot of subscriptions, but they seem to have some problems. In my case, there is a custom external component that, on startup, dynamically creates subscriptions within the context broker if they do not exist yet.

However, I noticed that the subscriptions will not fire notifications after a while of being created. As an example, I started my prototype application today and the subscriptions that were created yesterday did not fire. I'm not sure how this happens or what the specific conditions are, but the /ngsi-ld/v1/subscriptions/ endpoint showed the subscriptions without the timesSent, lastNotification, lastFailure,... metadata, indicating that they never sent any notifications. My solution in this situation is to delete all subscriptions, restart that custom component, it recreates all subscriptions in exactly the same way, and then it works again.

Almost all of my subscriptions have the same properties, so maybe it has something to do with certain features? Below is an example of such a subscription:

  {
       "id": "urn:ngsi-ld:Subscription:transport1",
       "type": "Subscription",
       "description": "Policy modifier rule transport1 subscription",
       "entities": [
           {
               "type": "Transport"
           }
       ],
       "watchedAttributes": [
           "status"
       ],
       "q": "status==%22Created%22",
       "status": "active",
       "isActive": true,
       "notification": {
           "attributes": [
               "issuer",
               "cargo_ids",
               "carrier",
               "from_company",
               "to_company"
           ],
           "format": "keyValues",
           "endpoint": {
               "uri": "[custom-IP]",
               "accept": "application/json"
           },
           "status": "ok",
           "timesSent": 1,
           "lastNotification": "2023-06-19T18:42:31.312Z",
           "lastFailure": "2023-06-19T18:42:31.314Z"
       }
   },

Any idea as to why this might happen?

The text was updated successfully, but these errors were encountered:

kzangeli · 2023-06-20T07:51:31Z

ok, that's not good !

I'd like you to test something, let me explain ...

I've been working quite a while on getting rid of the old deprecated mongo driver.
The work is done, it is fairly tested, but I still need to do more tests before making it default.
Especially concurrency tests. Actually, only concurrency tests are missing at this point.

Anyway, this work reimplements the entire database layer and with that quite a lot of the logic. I'd say about 33% of the broker has been rewritten.

I'd like you to test the new implementation, as, fixing bugs in the old deprecated code is not something I really have time for.

So, please start the broker with the option -experimental, or env var `ORIONLD_EXPERIMENTAL=TRUE

Might be your problem is fixed in "experimental mode".
And, don't worry, the name "experimental" is old, from when I just started the new implementation.
It's no longer experimental. I'll rename the CLI to -mongoc (suggesting the usage of the new mongo driver)

Please test this and let me know.`

Jxlle · 2023-06-20T12:41:45Z

Hi @kzangeli,

I switched to experimental. I'll let you know if the problem still exists tomorrow!
One thing I noticed however is that my Kong instance that handles all incoming orion-ld requests timed out while reading the response header from orion. This has never happened before I enabled experimental. Do you know why this might happen?

i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 12:29:04 [debug] 1114#0: *12009 [lua] base_plugin.lua:26: access(): executing plugin "ngsi-ishare-policies": access
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 12:29:04 [debug] 1114#0: *12009 [kong] handler.lua:85 [ngsi-ishare-policies]  *** NGSI-iSHARE-Policies plugin access() function entered ***
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 12:29:04 [debug] 1114#0: *12009 [kong] handler.lua:88 [ngsi-ishare-policies] Reading access token from request
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 12:29:05 [debug] 1114#0: *12009 [kong] handler.lua:156 [ngsi-ishare-policies] *** Access granted ***
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 12:29:05 [debug] 1114#0: *12009 [lua] init.lua:1006: balancer(): setting address (try 1): 52.31.1.45:1026
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 12:29:05 [debug] 1114#0: *12009 [lua] init.lua:1035: balancer(): enabled connection keepalive (pool=52.31.1.45|1026, pool_size=60, idle_timeout=60, max_requests=100)
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 12:30:05 [error] 1114#0: *12009 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 52.31.1.45, server: kong, request: "POST /context-broker/ngsi-ld/v1/entities/? HTTP/1.1", upstream: "http://52.31.1.45:1026/ngsi-ld/v1/entities/?", host: "52.31.1.45:8080"
i4trust-stakeholder-mvp-stack-kong-1                | 52.31.1.45 - - [20/Jun/2023:12:30:05 +0000] "POST /context-broker/ngsi-ld/v1/entities/? HTTP/1.1" 504 51 "-" "-"

kzangeli · 2023-06-20T13:08:27Z

Sorry, not a clue.
Perhaps yopu have traces from the broker?

[ Surprised to see "POST /context-broker/ngsi-ld/v1/entities/?" ... Question mark without url params??? ]

Jxlle · 2023-06-20T13:34:13Z

Yeah that's just my component that generates Kong calls, if there are no parameters it still inserts the '?'. I can change that but it worked until now :p

Sorry, seems that I missed the orion trace indeed, this is the full (relevant) trace:

i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 12:29:05 [debug] 1114#0: *12009 [lua] init.lua:1006: balancer(): setting address (try 1): 52.31.1.45:1026
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 12:29:05 [debug] 1114#0: *12009 [lua] init.lua:1035: balancer(): enabled connection keepalive (pool=52.31.1.45|1026, pool_size=60, idle_timeout=60, max_requests=100)
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 12:30:05 [error] 1114#0: *12009 upstream timed out (110: Operation timed out) while reading response header from upstream, client: [], server: kong, request: "POST /context-broker/ngsi-ld/v1/entities/? HTTP/1.1", upstream: "http://52.31.1.45:1026/ngsi-ld/v1/entities/?", host: "52.31.1.45:8080"
i4trust-stakeholder-mvp-stack-kong-1                | 52.31.1.45 - - [20/Jun/2023:12:30:05 +0000] "POST /context-broker/ngsi-ld/v1/entities/? HTTP/1.1" 504 51 "-" "-"
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 12:30:05 2023.287Z | lvl=ERROR | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[394]:notificationResponseTreat | msg=Internal Error (urn:ngsi-ld:Subscription:transport6: non 2xx response (500) to notification on fd 27)
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 12:30:05 2023.288Z | lvl=TMP | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[982]:orionldMhdConnectionInit | msg=------------------------- Servicing NGSI-LD request 017: POST /ngsi-ld/v1/entities/ --------------------------

My component (C) and context broker (B) interact like this:
User: changes entity via Kong
B: generate notification for subscription
C: Get notification, while still not returning a notification response, handle other stuff including other context broker calls (e.g. create new entities)
B: Get other context broker calls while still not having received a response for the notification
C: If everything worked, send status code 200, otherwise send another response code
B: Receive response code for notification and log this

Could it be that the experimental version of the context broker cannot handle an incoming request while a notification request is still being processed? The log shows that the Kong module fails before the orion-ld notification fails, and only after that, the POST request comes through. However, the POST request should be executed before the notification fails, as it was sent before the notification status code was sent. You can also see this in the logs of the custom module: The new request is the notification, the status code is only returned at the end of the log.

Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Request successfully processed: OK
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0]  Received request:
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0]         -> Request count: 14
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0]         -> HTTP method: POST
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0]         -> Client IP address: 52.31.1.45
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0]         -> User host name: orion-ld
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0]         -> Agent: orionld/post-v1.2.0
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0]         -> Headers: {Content-Length: [418], Content-Type: [application/json], User-Agent: [orionld/post-v1.2.0], Host: [orion-ld], Accept: [application/json], Ngsild-Attribute-Format: [Simplified], Link: [<https://datamodels.ouranos-ws.com/globshare/10/context.jsonld>; rel="http://www.w3.org/ns/json-ld#context"; type="application/ld+json"]}
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0]         -> Body: {"id":"urn:ngsi-ld:Notification:07329fd0-0f66-11ee-88f1-0242c0a85007","type":"Notification","subscriptionId":"urn:ngsi-ld:Subscription:transport6","notifiedAt":"2023-06-20T12:28:57.683Z","data":[{"id":"urn:ngsi-ld:Transport:003","type":"Transport","cargo_ids":["urn:ngsi-ld:Cargo:003"],"issuer":"EU.EORI.RENORYTEST","carrier":"EU.EORI.ABCTRUCKINGTEST","from_company":"EU.EORI.AMLTEST","to_company":"EU.EORI.AMMTEST"}]}
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Validating request...
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Processing normal notification...
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Processing entity effects...
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Processing policy effects...
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Creating delegation evidence with issuer EU.EORI.GLOBSHARETEST and subject EU.EORI.RENORYTEST...
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Creating delegation evidence with issuer EU.EORI.GLOBSHARETEST and subject EU.EORI.ABCTRUCKINGTEST...
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Creating delegation evidence with issuer EU.EORI.GLOBSHARETEST and subject EU.EORI.AMLTEST...
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Creating delegation evidence with issuer EU.EORI.GLOBSHARETEST and subject EU.EORI.AMMTEST...
Jun 20 12:29:01 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Creating iSHARE JWT...
Jun 20 12:29:02 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Requesting access token at http://52.31.1.45:3000/oauth2/token...
Jun 20 12:29:04 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Access token received for GlobShare (EU.EORI.GLOBSHARETEST).
Jun 20 12:29:04 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Sending POST request to http://52.31.1.45:8080/context-broker/ngsi-ld/v1/entities/?...
Jun 20 12:30:05 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[317046]: i4trustConsoleApp.PolicyModifier[0] Skipping request: GatewayTimeout:{   "message":"The upstream server is timing out" }

kzangeli · 2023-06-20T13:39:31Z

See this in the traces?

Internal Error (urn:ngsi-ld:Subscription:transport6: non 2xx response (500) to notification on fd 27)

Seems like the receiver of the notification responds with a 500.
Possibly this happened before as well, but wasn't checked.

Let's go one step more then.
Traces from "whatever process" receives the notification?

[ The entire subscription/notification algorithm has been reimplemented from scratch ]

Jxlle · 2023-06-20T13:44:29Z

Yeah, that's my custom component. It just returns 500 if it fails to process the request fully. The traces at the bottom of my previous reply are the traces of the component that receives the notification.

In this case, the custom component receives a request with a specific subscription id, in this case it's transport6. Locally, the custom component has a set of rules it has to follow for each incoming request. In this case, it needs to create new entities when a transport6 notification comes in, based on the information inside the notification body. It tries to create the new entity, but fails as it receives a timeout from te context broker. Up until this point, the notification request is still not closed by this component, no status code has been sent. If the entity was created, or the entity already existed, it would've responded with a 200 OK. Because I didn't know at the time what could go wrong, I just chose to respond with a status code 500 in the case that something else failed. In this case, the custom component got a failed request from Kong, which got a timeout from orion, thus the custom component returns status code 500. (or is it better to just always return 200 when the notification was received?)

What I find weird in the logs, is that orion shows the failed notification first, and then it handles the POST. But the POST was requested (by the custom component) bfore it ever returned a notification status code.

I could be wrong, maybe I'm looking over something, but I never had this problem with the non-experimental version

kzangeli · 2023-06-20T14:01:48Z

It tries to create the new entity, but fails as it receives a timeout from the context broker

Only thing I saw in the brokers traces was a timeout in the response of the notification.

We'll need more info to understand the problem here.

And, to answer a question you made earlier:
All incoming requests run in separate threads. There is no such thing as one request blocking due to another request.
Well, I hope not :)
If that happens, it would be a problem with some semaphore, something I doubt.

Need more traces from the broker.
What goes wrong in this entity creation triggered by a notification ?

Jxlle · 2023-06-20T14:25:02Z

@kzangeli
This is the full trace, similar example, a notification comes in (subscription id = transport1), and a new entity needs to be created of type Cargo, but it fails:

i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 14:22:58 [debug] 1115#0: *1351 [lua] base_plugin.lua:26: access(): executing plugin "ngsi-ishare-policies": access
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 14:22:58 [debug] 1115#0: *1351 [kong] handler.lua:85 [ngsi-ishare-policies]  *** NGSI-iSHARE-Policies plugin access() function entered ***
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 14:22:58 [debug] 1115#0: *1351 [kong] handler.lua:88 [ngsi-ishare-policies] Reading access token from request
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 14:22:59 [debug] 1115#0: *1351 [kong] handler.lua:156 [ngsi-ishare-policies] *** Access granted ***
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 14:22:59 [debug] 1115#0: *1351 [lua] init.lua:1006: balancer(): setting address (try 1): 52.31.1.45:1026
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 14:22:59 [debug] 1115#0: *1351 [lua] init.lua:1035: balancer(): enabled connection keepalive (pool=52.31.1.45|1026, pool_size=60, idle_timeout=60, max_requests=100)
i4trust-stakeholder-mvp-stack-kong-1                | 2023/06/20 14:23:59 [error] 1115#0: *1351 upstream timed out (110: Operation timed out) while reading response header from upstream, client: 52.31.1.45, server: kong, request: "POST /context-broker/ngsi-ld/v1/entities/? HTTP/1.1", upstream: "http://52.31.1.45:1026/ngsi-ld/v1/entities/?", host: "52.31.1.45:8080"
i4trust-stakeholder-mvp-stack-kong-1                | 52.31.1.45 - - [20/Jun/2023:14:23:59 +0000] "POST /context-broker/ngsi-ld/v1/entities/? HTTP/1.1" 504 51 "-" "-"
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.685Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[245]:notificationResponseRead | msg=urn:ngsi-ld:Subscription:transport1: notification response Start-Line:   'HTTP/1.1 500 Internal Server Error'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.685Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[246]:notificationResponseRead | msg=urn:ngsi-ld:Subscription:transport1: notification response HTTP Headers: 'Server: Microsoft-NetCore/2.0
i4trust-stakeholder-mvp-stack-orion-ld-1            | Date: Tue, 20 Jun 2023 14:23:59 GMT
i4trust-stakeholder-mvp-stack-orion-ld-1            | Content-Length: 66
i4trust-stakeholder-mvp-stack-orion-ld-1            | Connection: close'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.686Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[247]:notificationResponseRead | msg=GatewayTimeout:{
i4trust-stakeholder-mvp-stack-orion-ld-1            |   "message":"The upstream server is timing out"
i4trust-stakeholder-mvp-stack-orion-ld-1            | }: notification response body so far: ''
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.686Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[271]:notificationResponseRead | msg=urn:ngsi-ld:Subscription:transport1: Content-Length: 66
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.686Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[280]:notificationResponseRead | msg=urn:ngsi-ld:Subscription:transport1: total no of bytes read: 211
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.686Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[281]:notificationResponseRead | msg=urn:ngsi-ld:Subscription:transport1: no of bytes of body read: 66
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.686Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[336]:notificationResponseRead | msg=urn:ngsi-ld:Subscription:transport1: entire message read
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.686Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[374]:notificationResponseTrea' | msg=urn:ngsi-ld:Subscription:transport1: Notification Response HTTP Header: 'Server: Microsoft-NetCore/2.0
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.687Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[374]:notificationResponseTrea' | msg=urn:ngsi-ld:Subscription:transport1: Notification Response HTTP Header: 'Date: Tue, 20 Jun 2023 14:23:59 GMT
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.687Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[374]:notificationResponseTrea' | msg=urn:ngsi-ld:Subscription:transport1: Notification Response HTTP Header: 'Content-Length: 66
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.687Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[378]:notificationResponseTreat | msg=urn:ngsi-ld:Subscription:transport1: Notification Response HTTP Header: 'Connection: close'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.688Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[381]:notificationResponseTreat | msg=urn:ngsi-ld:Subscription:transport1: Notification Response Body: 'GatewayTimeout:{
i4trust-stakeholder-mvp-stack-orion-ld-1            |   "message":"The upstream server is timing out"
i4trust-stakeholder-mvp-stack-orion-ld-1            | }'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.688Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=notificationFailure.cpp[44]:notificationFailure | msg=urn:ngsi-ld:Subscription:transport1: notification failure (timestamp: 1687270975.968321)
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.688Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=notificationFailure.cpp[67]:notificationFailure | msg=urn:ngsi-ld:Subscription:transport1: dirty: 1, cSubCounters: 20
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.688Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=notificationFailure.cpp[88]:notificationFailure | msg=urn:ngsi-ld:Subscription:transport1: Not calling mongocSubCountersUpdate (cSubCounters: 20, dirty: 1, forcedToPause: false)
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.688Z | lvl=ERROR | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldAlterationsTreat.cpp[394]:notificationResponseTreat | msg=Internal Error (urn:ngsi-ld:Subscription:transport1: non 2xx response (500) to notification on fd 26)
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.688Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=notificationFailure.cpp[44]:notificationFailure | msg=urn:ngsi-ld:Subscription:test: notification failure (timestamp: 1687270975.968321)
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.688Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=notificationFailure.cpp[67]:notificationFailure | msg=urn:ngsi-ld:Subscription:test: dirty: 1, cSubCounters: 20
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.689Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=notificationFailure.cpp[88]:notificationFailure | msg=urn:ngsi-ld:Subscription:test: Not calling mongocSubCountersUpdate (cSubCounters: 20, dirty: 1, forcedToPause: false)
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.689Z | lvl=TMP | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[982]:orionldMhdConnectionInit | msg=------------------------- Servicing NGSI-LD request 030: POST /ngsi-ld/v1/entities/ --------------------------
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.689Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[406]:orionldHttpHeaderReceive | msg=Got an HTTP Header: 'Host': '52.31.1.45:1026'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.689Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[406]:orionldHttpHeaderReceive | msg=Got an HTTP Header: 'Connection': 'keep-alive'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.689Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[406]:orionldHttpHeaderReceive | msg=Got an HTTP Header: 'X-Forwarded-For': '52.31.1.45'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.689Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[406]:orionldHttpHeaderReceive | msg=Got an HTTP Header: 'X-Forwarded-Proto': 'http'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.690Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[406]:orionldHttpHeaderReceive | msg=Got an HTTP Header: 'X-Forwarded-Host': '52.31.1.45'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.690Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[406]:orionldHttpHeaderReceive | msg=Got an HTTP Header: 'X-Forwarded-Port': '8080'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.690Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[406]:orionldHttpHeaderReceive | msg=Got an HTTP Header: 'X-Forwarded-Path': '/context-broker/ngsi-ld/v1/entities/'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.690Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[406]:orionldHttpHeaderReceive | msg=Got an HTTP Header: 'X-Forwarded-Prefix': '/context-broker'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.690Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[406]:orionldHttpHeaderReceive | msg=Got an HTTP Header: 'X-Real-IP': '52.31.1.45'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.690Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[406]:orionldHttpHeaderReceive | msg=Got an HTTP Header: 'Content-Length': '173'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.690Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[406]:orionldHttpHeaderReceive | msg=Got an HTTP Header: 'Link': '<https://datamodels.ouranos-ws.com/globshare/10/context.jsonld>; rel="http://www.w3.org/ns/json-ld#context"; type="application/ld+json"''
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.691Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[406]:orionldHttpHeaderReceive | msg=Got an HTTP Header: 'Cookie': 'session=eyJyZWRpciI6Ii8ifQ==; session.sig=uSSXAIZyordaCJqLj9tDK5NLYLE'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.691Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[406]:orionldHttpHeaderReceive | msg=Got an HTTP Header: 'Content-Type': 'application/json; charset=utf-8'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.691Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionTreat.cpp[1113]:orionldMhdConnectionTreat | msg=Request Payload Body: {"commodity":"","quantity":"0","weight":"0","packaging_type":"","product_id":"0","product_description":"","marks_and_numbers":""}
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.699Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=restReply.cpp[77]:restReply | msg=Response Body: 'None'
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.699Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=restReply.cpp[78]:restReply | msg=Response Code:  201
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.701Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=pgCommands.cpp[59]:pgCommands | msg=SQL: INSERT INTO entities(instanceId,ts,opMode,id,type) VALUES ('urn:ngsi-ld:attribute:instance:191d9bae-0f76-11ee-989d-0242c0a88007', '2023-06-20T14:23:59.689Z', 'Create', 'urn:ngsi-ld:Cargo:001', 'https://ngsi-ld.ouranos-ws.com/Cargo');
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.701Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=pgCommands.cpp[59]:pgCommands | msg=SQL: INSERT INTO attributes(instanceId,id,opMode,entityId,observedAt,subProperties,unitCode,datasetId,valueType,text,boolean,number,datetime,compound,geoPoint,geoMultiPoint,geoPolygon,geoMultiPolygon,geoLineString,geoMultiLineString,ts) VALUES ('urn:ngsi-ld:attribute:instance:191d9c6c-0f76-11ee-989d-0242c0a88007', 'https://ngsi-ld.ouranos-ws.com/commodity', 'Create', 'urn:ngsi-ld:Cargo:001', null, false, null, 'None', 'String', '', null, null, null, null, null, null, null, null, null, null, '2023-06-20T14:23:59.689Z'),('urn:ngsi-ld:attribute:instance:191d9d0c-0f76-11ee-989d-0242c0a88007', 'https://ngsi-ld.ouranos-ws.com/quantity', 'Create', 'urn:ngsi-ld:Cargo:001', null, false, null, 'None', 'String', '0', null, null, null, null, null, null, null, null, null, null, '2023-06-20T14:23:59.689Z'),('urn:ngsi-ld:attribute:instance:191d9d84-0f76-11ee-989d-0242c0a88007', 'https://ngsi-ld.ouranos-ws.com/weight', 'Create', 'urn:ngsi-ld:Cargo:001', null, false, null, 'None', 'String', '0', null, null, null, null, null, null, null, null, null, null, '2023-06-20T14:23:59.689Z'),('urn:ngsi-ld:attribute:instance:191d9e06-0f76-11ee-989d-0242c0a88007', 'https://ngsi-ld.ouranos-ws.com/packaging_type', 'Create', 'urn:ngsi-ld:Cargo:001', null, false, null, 'None', 'String', '', null, null, null, null, null, null, null, null, null, null, '2023-06-20T14:23:59.689Z'),('urn:ngsi-ld:attribute:instance:191d9e92-0f76-11ee-989d-0242c0a88007', 'https://ngsi-ld.ouranos-ws.com/product_id', 'Create', 'urn:ngsi-ld:Cargo:001', null, false, null, 'None', 'String', '0', null, null, null, null, null, null, null, null, null, null, '2023-06-20T14:23:59.689Z'),('urn:ngsi-ld:attribute:instance:191d9f0a-0f76-11ee-989d-0242c0a88007', 'https://ngsi-ld.ouranos-ws.com/product_description', 'Create', 'urn:ngsi-ld:Cargo:001', null, false, null, 'None', 'String', '', null, null, null, null, null, null, null, null, null, null, '2023-06-20T14:23:59.689Z'),('urn:ngsi-ld:attribute:instance:191d9f8c-0f76-11ee-989d-0242c0a88007', 'https://ngsi-ld.ouranos-ws.com/marks_and_numbers', 'Create', 'urn:ngsi-ld:Cargo:001', null, false, null, 'None', 'String', '', null, null, null, null, null, null, null, null, null, null, '2023-06-20T14:23:59.689Z');
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.704Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=subCacheAlterationMatch.cpp[99]:entityTypeMatch | msg=Sub 'urn:ngsi-ld:Subscription:test': no match due to Entity Type
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.704Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=subCacheAlterationMatch.cpp[99]:entityTypeMatch | msg=Sub 'urn:ngsi-ld:Subscription:transport1': no match due to Entity Type
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.704Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=subCacheAlterationMatch.cpp[99]:entityTypeMatch | msg=Sub 'urn:ngsi-ld:Subscription:transport2': no match due to Entity Type
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.704Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=subCacheAlterationMatch.cpp[99]:entityTypeMatch | msg=Sub 'urn:ngsi-ld:Subscription:transport3': no match due to Entity Type
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.704Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=subCacheAlterationMatch.cpp[99]:entityTypeMatch | msg=Sub 'urn:ngsi-ld:Subscription:transport4': no match due to Entity Type
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.704Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=subCacheAlterationMatch.cpp[99]:entityTypeMatch | msg=Sub 'urn:ngsi-ld:Subscription:transport5': no match due to Entity Type
i4trust-stakeholder-mvp-stack-orion-ld-1            | time=Tuesday 20 Jun 14:23:59 2023.704Z | lvl=DEBUG | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=subCacheAlterationMatch.cpp[99]:entityTypeMatch | msg=Sub 'urn:ngsi-ld:Subscription:transport6': no match due to Entity Type

kzangeli · 2023-06-20T14:25:54Z

ORION_TRACE ... that's not the right env var - wrong prefix (for Orion, not Orion-LD)

ORIONLD_TRACE
ORIONLD_LOG_LEVEL

Jxlle · 2023-06-20T14:26:17Z

ORION_TRACE ... that's not the right env var - wrong prefix (for Orion, not Orion-LD)

ORIONLD_TRACE

ORIONLD_LOG_LEVEL

Yeah I changed that, I deleted the reply because I noticed the error :)
My other reply contains the full trace

kzangeli · 2023-06-20T14:27:57Z

Yeah, I noticed.

Seems like you get no notification due to an entity type mismatch.
Pity we don't have more details. Might have to extend the traces a little

Jxlle · 2023-06-20T14:37:55Z

@kzangeli
I think the notification type mismatches are valid because the newly created entity is of type Cargo and the subscriptions are all on Transport. The POST request (creation of the Cargo entity when a transport1 notification gets received by my custom component) gets executed, but from the logs it seems that it only executes after the gatewaytimeout (and not before like it should)?

kzangeli · 2023-06-20T14:39:22Z

So, after the timed out notification we see this:

  Servicing NGSI-LD request 030: POST /ngsi-ld/v1/entities/
  Request Payload Body: {"commodity":"","quantity":"0","weight":"0","packaging_type":"","product_id":"0", ...
  Response Code:  201

So, that creation seems to have worked.

I'll have a look at the timeout for notifications (I might have hardcoded that to 5 secs or something).
I'll make it configurable from command line / env var and we can try with a higher value.

Also, as you might have seen, the entity id/type are not present in the traces (Request Payload Body).
That's because Orion-LD takes them out before that log-line.
I'll add those two as well.
Need to see those two (especially the entity type).

Jxlle · 2023-06-20T14:41:38Z

Also, as you might have seen, the entity id/type are not present in the traces (Request Payload Body). That's because Orion-LD takes them out before that log-line. I'll add those two as well. Need to see those two (especially the entity type).

The entity type was Cargo, the id was urn:ngsi-ld:Cargo:001. A link header was provided with a link to the context file. I can edit my custom component to show more detailed logs and paste them here if you want, with all the detailed request info.

Jxlle · 2023-06-23T12:29:46Z

Hi @kzangeli,

I initially forgot to reply with my full custom component log, sorry!
This is the full log of my custom component (with some redacted info for readability). Entity creation happens at the bottom of the log (you read the full json object there). The other components (kong/orion-ld) reacted in the same way as my older replies so I emitted those logs.

NOTE: I can create Cargo entities just fine if I directly do the call via postman/console application. The problem only seems to occur when a notification is being processed, such as the situation described in the logs.

Jun 23 12:09:45 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Starting policy modifier...
Jun 23 12:09:45 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Trying to start listener on http://*:8099/...
Jun 23 12:09:45 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Listening for connections on http://52.31.1.45:8099/...
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Added new request to queue.
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: Received request:
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> Request count: 1
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> HTTP method: POST
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> Client IP address: 52.31.1.45
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> User host name: orion-ld
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> Agent: orionld/post-v1.2.0
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Added new request to queue.
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> Headers: {Content-Length: [374], Content-Type: [application/json], User-Agent: [orionld/post-v1.2.0], Host: [orion-ld], Accept: [application/json], Ngsild-Attribute-Format: [Concise], Link: [<https://datamodels.ouranos-ws.com/globshare/10/context.jsonld>; rel="http://www.w3.org/ns/json-ld#context"; type="application/ld+json"], email: [test]}
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> Body: {"id":"urn:ngsi-ld:Notification:aa06d404-11c0-11ee-a2a2-0242c0a88007","type":"Notification","subscriptionId":"urn:ngsi-ld:Subscription:test","notifiedAt":"2023-06-23T12:22:47.885Z","data":[{"id":"urn:ngsi-ld:Transport:005","type":"Transport","issuer":"EU.EORI.AMLTEST","carrier":"EU.EORI.ABCTRUCKINGTEST","from_company":"EU.EORI.RENORYTEST","to_company":"EU.EORI.AMMTEST"}]}
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Validating request...
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Processing email notification...
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Warn] Sending email notification...
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Warn] Skipping request: Sending email notification failed: The specified string is not in the form required for an e-mail address.
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: Received request:
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> Request count: 2
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> HTTP method: POST
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> Client IP address: 52.31.1.45
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> User host name: orion-ld
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> Agent: orionld/post-v1.2.0
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> Headers: {Content-Length: [418], Content-Type: [application/json], User-Agent: [orionld/post-v1.2.0], Host: [orion-ld], Accept: [application/json], Ngsild-Attribute-Format: [Simplified], Link: [<https://datamodels.ouranos-ws.com/globshare/10/context.jsonld>; rel="http://www.w3.org/ns/json-ld#context"; type="application/ld+json"]}
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info]         -> Body: {"id":"urn:ngsi-ld:Notification:aa0617d0-11c0-11ee-a2a2-0242c0a88007","type":"Notification","subscriptionId":"urn:ngsi-ld:Subscription:transport1","notifiedAt":"2023-06-23T12:22:47.885Z","data":[{"id":"urn:ngsi-ld:Transport:005","type":"Transport","cargo_ids":["urn:ngsi-ld:Cargo:010"],"issuer":"EU.EORI.AMLTEST","carrier":"EU.EORI.ABCTRUCKINGTEST","from_company":"EU.EORI.RENORYTEST","to_company":"EU.EORI.AMMTEST"}]}
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Validating request...
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Processing normal notification...
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Processing entity effects...
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Processing policy effects...
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Creating delegation evidence with issuer EU.EORI.GLOBSHARETEST and subject EU.EORI.AMLTEST...
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Debug] Delegation evidence: REDACTED
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Creating delegation evidence with issuer EU.EORI.GLOBSHARETEST and subject EU.EORI.ABCTRUCKINGTEST...
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Debug] Delegation evidence: REDACTED
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Creating delegation evidence with issuer EU.EORI.GLOBSHARETEST and subject EU.EORI.RENORYTEST...
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Debug] Delegation evidence: REDACTED
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Creating delegation evidence with issuer EU.EORI.GLOBSHARETEST and subject EU.EORI.AMMTEST...
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Debug] Delegation evidence: REDACTED
Jun 23 12:22:47 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Creating iSHARE JWT...
Jun 23 12:22:48 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Requesting access token at http://52.31.1.45:3000/oauth2/token...
Jun 23 12:22:50 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Access token received for GlobShare (EU.EORI.GLOBSHARETEST).
Jun 23 12:22:50 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Debug] Access token:
Jun 23 12:22:50 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: REDACTED
Jun 23 12:22:50 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Info] Sending POST request to http://52.31.1.45:8080/context-broker/ngsi-ld/v1/entities/?...
Jun 23 12:22:50 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Debug]         -> Content: {"commodity":"","quantity":"0","weight":"0","packaging_type":"","product_id":"0","product_description":"","marks_and_numbers":"","id":"urn:ngsi-ld:Cargo:010","type":"Cargo"}
Jun 23 12:22:50 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Debug]         -> Headers:
Jun 23 12:22:50 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Debug]                 Link: [<https://datamodels.ouranos-ws.com/globshare/10/context.jsonld>; rel="http://www.w3.org/ns/json-ld#context"; type="application/ld+json"']
Jun 23 12:22:50 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Debug]                 Authorization: [Bearer REDACTED]
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Debug] Response:
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: StatusCode: 504, ReasonPhrase: 'Gateway Time-out', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: {
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]:   Date: Fri, 23 Jun 2023 12:23:51 GMT
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]:   Connection: keep-alive
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]:   X-Kong-Upstream-Latency: 60004
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]:   X-Kong-Proxy-Latency: 1582
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]:   Via: kong/2.8.1
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]:   Content-Type: application/json; charset=utf-8
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]:   Content-Length: 51
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: }
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: [Warn] Skipping request: GatewayTimeout:{
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]:   "message":"The upstream server is timing out"
Jun 23 12:23:51 ip-192-168-55-33.eu-west-1.compute.internal i4trustConsoleApp[1704833]: }

Jxlle · 2023-07-19T08:02:23Z

Hi @kzangeli

Is there any progress on this issue, or is it totally unknown as to what the cause of the problem might be? (both the subscriptions not working after a while in non-experimental mode and the issue with experimental mode). No hurry though, I'm just curious :)

kzangeli · 2023-07-19T08:45:04Z

Yeah, very sorry, haven't had time for this yet.
The issue is on my radar, quite high up in my priority list.
Hopefully I will have next to zero distractions in August and I can finally get things done!

Jxlle · 2023-10-13T11:25:12Z

Hi @kzangeli, any updates on this? Just in case I missed something :)

kzangeli · 2023-10-16T08:53:04Z

Sorry, just back from vacation and no progress on this issue.
And, unfortunately,, I have quite the list of things I need to look at asap.
Not sure when I'll finally get time to look into this :(

kzangeli mentioned this issue Jun 23, 2023

Planning #280

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Notification problems after a while #1390

Notification problems after a while #1390

Jxlle commented Jun 19, 2023 •

edited

Loading

kzangeli commented Jun 20, 2023

Jxlle commented Jun 20, 2023

kzangeli commented Jun 20, 2023

Jxlle commented Jun 20, 2023 •

edited

Loading

kzangeli commented Jun 20, 2023 •

edited

Loading

Jxlle commented Jun 20, 2023 •

edited

Loading

kzangeli commented Jun 20, 2023

Jxlle commented Jun 20, 2023

kzangeli commented Jun 20, 2023

Jxlle commented Jun 20, 2023 •

edited

Loading

kzangeli commented Jun 20, 2023

Jxlle commented Jun 20, 2023 •

edited

Loading

kzangeli commented Jun 20, 2023

Jxlle commented Jun 20, 2023 •

edited

Loading

Jxlle commented Jun 23, 2023 •

edited

Loading

Jxlle commented Jul 19, 2023

kzangeli commented Jul 19, 2023

Jxlle commented Oct 13, 2023

kzangeli commented Oct 16, 2023

Notification problems after a while #1390

Notification problems after a while #1390

Comments

Jxlle commented Jun 19, 2023 • edited Loading

kzangeli commented Jun 20, 2023

Jxlle commented Jun 20, 2023

kzangeli commented Jun 20, 2023

Jxlle commented Jun 20, 2023 • edited Loading

kzangeli commented Jun 20, 2023 • edited Loading

Jxlle commented Jun 20, 2023 • edited Loading

kzangeli commented Jun 20, 2023

Jxlle commented Jun 20, 2023

kzangeli commented Jun 20, 2023

Jxlle commented Jun 20, 2023 • edited Loading

kzangeli commented Jun 20, 2023

Jxlle commented Jun 20, 2023 • edited Loading

kzangeli commented Jun 20, 2023

Jxlle commented Jun 20, 2023 • edited Loading

Jxlle commented Jun 23, 2023 • edited Loading

Jxlle commented Jul 19, 2023

kzangeli commented Jul 19, 2023

Jxlle commented Oct 13, 2023

kzangeli commented Oct 16, 2023

Jxlle commented Jun 19, 2023 •

edited

Loading

Jxlle commented Jun 20, 2023 •

edited

Loading

kzangeli commented Jun 20, 2023 •

edited

Loading

Jxlle commented Jun 20, 2023 •

edited

Loading

Jxlle commented Jun 20, 2023 •

edited

Loading

Jxlle commented Jun 20, 2023 •

edited

Loading

Jxlle commented Jun 20, 2023 •

edited

Loading

Jxlle commented Jun 23, 2023 •

edited

Loading