The Orion LD dies on external targets of a notification.

[FR-ADDIX]

Our platform is a K8S in version 1.25.6
with a fiware/orion-ld:1.2.0-PRE-1255
the MongoDB is in version 6
we use the orion with -mongocOnly

We have the problem that we can't send subscriptions to a target outside our own namespace.
This is the subscribtion:

{ "id": "urn:ngsi-ld:subscription:8f6f80a4-a7a4-11ed-9cbf-16804aa0063b", "type": "Subscription", "subscriptionName": "Notify NR WeatherObserved zu addixio", "description": "NR WeatherObserved zu addixio", "entities": [ { "idPattern": "WeatherObserved", "type": "WeatherObserved" } ], "watchedAttributes": [ "dateObserved" ], "status": "active", "isActive": true, "notification": { "attributes": [ "location", "atmosphericPressure", "dateObserved" ], "format": "normalized", "endpoint": { "uri": "http://node-red-captn.captn.svc/yvonne", "accept": "application/json" }, "status": "failed", "timesSent": 2, "lastNotification": "2023-02-08T11:35:20.386Z", "lastFailure": "2023-02-08T11:35:20.386Z", "consecutiveErrors": 2, "lastErrorReason": "Unable to connect to notification endpoint" }, "origin": "cache" }

The error message is:
"lastErrorReason": "Unable to connect to notification endpoint".

If we use the following test curl from the POD shell we reach the target:

curl --location --request POST 'http://node-red-captn.captn.svc/yvonne' \ --header 'Content-Type: application/json' \ --data-raw '{ "TEST": "Test2" }'

And now it becomes critical, we replace the target in the subscribtion with a target outside the cluster and if the subscribtion is then triggered the orion-ld dies and is restarted by the K8S.

The following subscribtion lets the orion-ld die:

{ "id": "urn:ngsi-ld:subscription:ee6bc6c4-a79c-11ed-a95a-4227d0e0e9ae", "type": "Subscription", "subscriptionName": "Notify NR WeatherObserved zu addixio", "description": "NR WeatherObserved zu addixio", "entities": [ { "idPattern": "WeatherObserved", "type": "WeatherObserved" } ], "watchedAttributes": [ "dateObserved" ], "status": "active", "isActive": true, "notification": { "attributes": [ "location", "atmosphericPressure", "dateObserved" ], "format": "normalized", "endpoint": { "uri": "https://nodered.staging.addix.io/yvonne", "accept": "application/json" }, "status": "ok" }, "origin": "cache" }

Grüße aus Kiel ;-)

[kzangeli]

ok, that's interresting!
Crashes are something I'm always very interested in fixing.

There's two issues here though.

1. Unable to connect to notification endpoint
2. CRASH !!!

Issue 1, might be I need to add some flag to libcurl.
Issue 2: is the only difference the endpoint?

Now, to help me reproduce, could you add the exact curl commends you do to see the errors?
Something like:

1. Create the subscription: curl -X POST -d " ... "
2. Create an entity to trigger a notification: POST /ngsi-ld/v1/entities -X POST -d " ... "

For "both issues".

Also, did you take a look inside the logfile? (/tmp/orionld.log). Might find something valuable in there.

Pass me also ALL CLI params. "-mongocOnly" and ... what more?

[FR-ADDIX]

Log for 1. Unable to connect to notification endpoint:

time=2023-02-08T11:35:22.427Z | lvl=ERROR | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldServerConnect.cpp[51]:orionldServerConnect | msg=unable to find host 'node-red-captn.captn.svc/yvonne' time=2023-02-08T11:35:22.427Z | lvl=ERROR | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=httpNotify.cpp[48]:httpNotify | msg=Internal Error (unable to connect to server for notification for subscription 'urn:ngsi-ld:subscription:8f6f80a4-a7a4-11ed-9cbf-16804aa0063b': Illegal seek)

curl for 1. add the subscribtion:

curl --location --request POST 'https://apis.captn.stag.addix.io/ngsi-ld/v1/subscriptions/' \ --header 'fiware-service: captn' \ --header 'fiware-servicepath: /' \ --header 'NGSILD-Tenant: captn' \ --header 'Authorization: Bearer {myToken}' \ --header 'Content-Type: application/json' \ --data-raw '{ "description": "NR WeatherObserved zu addixio", "type": "Subscription", "name": "Notify NR WeatherObserved zu addixio", "entities": [{ "idPattern": "WeatherObserved", "type": "WeatherObserved" }], "watchedAttributes": [ "dateObserved" ], "isActive": true, "notification": { "attributes": [ "location", "atmosphericPressure", "dateObserved" ], "format": "normalized", "endpoint": { "uri": "http://node-red-captn.captn.svc/yvonne", "accept": "application/json" } } }'

and the Entity update POST:

curl --location --request POST 'https://apis.captn.stag.addix.io/ngsi-ld/v1/entityOperations/upsert?options=update' \ --header 'fiware-service: captn' \ --header 'fiware-servicepath: /' \ --header 'NGSILD-Tenant: captn' \ --header 'Authorization: Bearer {myToken}' \ --header 'Content-Type: application/json' \ --data-raw '[ { "id": "urn:ngsi-ld:WeatherObserved:ADDIX:owm:54461020", "type": "WeatherObserved", "dateObserved": { "type": "Property", "value": { "@type": "DateTime", "@value": "2023-02-08T13:13:14.000Z" } }, "atmosphericPressure": { "type": "Property", "value": 1037 } } ]'

All the CLI parameter for orion-ld:

Args: -dbhost mongodb-headless.fiware.svc.cluster.local:27017 -logLevel DEBUG -ctxTimeout 10000 -experimental -mongocOnly
LOG for 2.
nothing :-(

yes, for 2. is the only difference the endpoint
This endpoint is outside of our cluster.

[kzangeli]

ok, perfect. Now I have more to go on!

[FR-ADDIX]

Oh, the duplicate headers are due to our APISIX GW, there we currently still have to pass the old Fiware service header.
If I create the objects within the cluster, I can do without the two Fiware headers with the same result.

Is it possible that your curl / libcurl only talks ipv6?
We would not support that in the cluster at the moment.

[kzangeli]

Finally got some time to look at this issue!

I created a new functest, as similar to your description as I could.
I use the exact same URL as notification endpoint as you do.
There is of course nobody on the other side, but, that's more or less what you're seeing as well so ...

I tried with both http and https for the notification endpoint (for http I use my own implementation and for https I use libcurl).
The batch operation works for both, and the noitification fails, of course, and with an error in the logfile:

With https:

orionldAlterationsTreat.cpp[444]:orionldAlterationsTreat : Notification Host: 'node-red-captn.captn.svc/yvonne'
orionldAlterationsTreat.cpp[445]:orionldAlterationsTreat : Notification Result for subscription 'urn:ngsi-ld:subscription:8f6f80a4-a7a4-11ed-9cbf-16804aa0063b': CURLcode 6 (Couldn't resolve host name)

With http:

orionldServerConnect.cpp[51]:orionldServerConnect : unable to find host 'node-red-captn.captn.svc/yvonne'
httpNotify.cpp[48]:httpNotify : Internal Error (unable to connect to server for notification for subscription 'urn:ngsi-ld:subscription:8f6f80a4-a7a4-11ed-9cbf-16804aa0063b')

One thing I just realized will not work with "my" implementation (http) is if you get a 302 Redirect. I haven't implemented the treatment of a 302. If you have 302s, then use https instead. Just until I get a chance to implement it (or, move to libcurl for http as well might be a good idea).

That's all I have right now ...

[FR-ADDIX]

Hm, with the endpoint https://nodered.staging.addix.io/yvonne we have a HTTPS endpoint, which you could also use and which is accessible for tests.
But that had crashed the orion-ld.
Can we see the logs shown also with us or is this an extended test version?

[kzangeli]

I did my tests with the very latest I'm working on right now but, those logs should be the exact same for you, if you use a not too old version of the broker.

[FR-ADDIX]

I have a local Docker installation set up and even with that via https I get a following error:

{ "id": "urn:ngsi-ld:subscription:545b3fce-b0f2-11ed-bae7-0242c0a8900a", "type": "Subscription", "subscriptionName": "Notify Test Yvonne", "description": "Test Yvonne externes Ziel", "entities": [ { "type": "Device" } ], "watchedAttributes": [ "dateObserved" ], "status": "active", "isActive": true, "notification": { "format": "normalized", "endpoint": { "uri": "https://nodered.staging.addix.io/yvonne", "accept": "application/json" }, "status": "failed", "timesSent": 1, "lastNotification": "2023-02-20T08:59:04.168Z", "lastFailure": "2023-02-20T08:59:04.168Z", "consecutiveErrors": 1, "lastErrorReason": "CURL Error 22: HTTP response code said error" }, "origin": "cache" }

Important insight: if I have two subscriptions that respond to the same action, the first one, which works alone, fails.

[ { "id": "urn:ngsi-ld:subscription:acbefeae-b074-11ed-bae7-0242c0a8900a", "type": "Subscription", "subscriptionName": "Notify Device changed", "description": "Notification ein neuer Device entsteht", "entities": [ { "type": "Device" } ], "watchedAttributes": [ "dateObserved" ], "status": "active", "isActive": true, "notification": { "format": "normalized", "endpoint": { "uri": "http://node-red:1880/notification", "accept": "application/json" }, "status": "failed", "timesSent": 37, "lastNotification": "2023-02-20T07:51:57.210Z", "lastFailure": "2023-02-20T07:51:57.210Z", "lastSuccess": "2023-02-20T07:51:57.210Z", "consecutiveErrors": 1, "lastErrorReason": "CURL Error 28: Timeout was reached" }, "origin": "cache" }, { "id": "urn:ngsi-ld:subscription:545b3fce-b0f2-11ed-bae7-0242c0a8900a", "type": "Subscription", "subscriptionName": "Notify Test Yvonne", "description": "Test Yvonne externes Ziel", "entities": [ { "type": "Device" } ], "watchedAttributes": [ "dateObserved" ], "status": "active", "isActive": true, "notification": { "format": "normalized", "endpoint": { "uri": "https://nodered.staging.addix.io/yvonne", "accept": "application/json" }, "status": "ok" }, "origin": "cache" } ]

[kzangeli]

ok, perfect. That's a very good clue.

About "HTTP response code said error". I'll add better log messages there, to give more info.
However, perhaps you can get that info already?
What exactly does the notification-receptor respond with?

[FR-ADDIX]

I cannot see what the answer to the request from Orion is.
The endpoint actually returns a code 200 directly.

If I call the endpoint directly with curl I get the following:

`url --location -v --request POST 'https://nodered.staging.addix.io/yvonne'

• Trying 212.51.10.76:443...
• Connected to nodered.staging.addix.io (212.51.10.76) port 443 (#0)
• ALPN, offering h2
• ALPN, offering http/1.1
• CAfile: /etc/ssl/certs/ca-certificates.crt
• CApath: /etc/ssl/certs
• TLSv1.0 (OUT), TLS header, Certificate Status (22):
• TLSv1.3 (OUT), TLS handshake, Client hello (1):
• TLSv1.2 (IN), TLS header, Certificate Status (22):
• TLSv1.3 (IN), TLS handshake, Server hello (2):
• TLSv1.2 (IN), TLS header, Finished (20):
• TLSv1.2 (IN), TLS header, Supplemental data (23):
• TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
• TLSv1.2 (IN), TLS header, Supplemental data (23):
• TLSv1.3 (IN), TLS handshake, Certificate (11):
• TLSv1.2 (IN), TLS header, Supplemental data (23):
• TLSv1.3 (IN), TLS handshake, CERT verify (15):
• TLSv1.2 (IN), TLS header, Supplemental data (23):
• TLSv1.3 (IN), TLS handshake, Finished (20):
• TLSv1.2 (OUT), TLS header, Finished (20):
• TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
• TLSv1.2 (OUT), TLS header, Supplemental data (23):
• TLSv1.3 (OUT), TLS handshake, Finished (20):
• SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
• ALPN, server accepted to use h2
• Server certificate:
• subject: CN=nodered.staging.addix.io
• start date: Feb 2 03:05:46 2023 GMT
• expire date: May 3 03:05:45 2023 GMT
• subjectAltName: host "nodered.staging.addix.io" matched cert's "nodered.staging.addix.io"
• issuer: C=US; O=Let's Encrypt; CN=R3
• SSL certificate verify ok.
• Using HTTP2, server supports multiplexing
• Connection state changed (HTTP/2 confirmed)
• Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
• TLSv1.2 (OUT), TLS header, Supplemental data (23):
• TLSv1.2 (OUT), TLS header, Supplemental data (23):
• TLSv1.2 (OUT), TLS header, Supplemental data (23):
• Using Stream ID: 1 (easy handle 0x55d900495b50)
• TLSv1.2 (OUT), TLS header, Supplemental data (23):

POST /yvonne HTTP/2
Host: nodered.staging.addix.io
user-agent: curl/7.81.0
accept: /

• TLSv1.2 (IN), TLS header, Supplemental data (23):
• TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
• TLSv1.2 (IN), TLS header, Supplemental data (23):
• Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
• TLSv1.2 (OUT), TLS header, Supplemental data (23):
• TLSv1.2 (IN), TLS header, Supplemental data (23):
• TLSv1.2 (IN), TLS header, Supplemental data (23):
• TLSv1.2 (IN), TLS header, Supplemental data (23):
  < HTTP/2 200
  < access-control-allow-origin: *
  < content-type: text/html; charset=utf-8
  < date: Mon, 20 Feb 2023 11:06:27 GMT
  < etag: W/"0-2jmj7l5rSw0yVb/vlWAYkK/YBwk"
  < strict-transport-security: max-age=31536000; includeSubDomains; preload
  < vary: Accept-Encoding
  < x-content-type-options: nosniff
  < x-frame-options: DENY
  < x-powered-by: Express
  < x-xss-protection: 1; mode=block
  < content-length: 0
  <
• Connection #0 to host nodered.staging.addix.io left intact
  `

[kzangeli]

So, I found a bug that I fixed. Not sure it has anything to do with your problems, but still.
I also added a bunch of log messages for notifications, both HTTP and HTTPS.
It's still running but the docker image should be available in 30 min or so.

Start your broker with -logLevel DEBUG -t 22 and let me know what you see (both HTTP and HTTPS notifications).

Sorry it's taken me soooo long this time. I've been really swamped lately :(

[FR-ADDIX]

Very interesting:
The Subscription HTTP: has an error message even though the data arrives.
The subscription on HTTPS: was not triggered according to Subscribtion.

The logs in Docker, as I understand them, say something completely different.

[ { "id": "urn:ngsi-ld:subscription:ce5211fc-b0fe-11ed-a7e7-0242c0a8900a", "type": "Subscription", "subscriptionName": "Notify Device changed", "description": "Notification ein neuer Device entsteht", "entities": [ { "type": "Device" } ], "watchedAttributes": [ "dateObserved" ], "status": "active", "isActive": true, "notification": { "format": "normalized", "endpoint": { "uri": "http://node-red:1880/notification", "accept": "application/json" }, "status": "failed", "timesSent": 3, "lastNotification": "2023-02-24T08:46:29.749Z", "lastFailure": "2023-02-24T08:46:29.749Z", "lastSuccess": "2023-02-24T08:46:29.749Z", "consecutiveErrors": 1, "lastErrorReason": "CURL Error 28: Timeout was reached" }, "origin": "cache" }, { "id": "urn:ngsi-ld:subscription:a592877a-b41d-11ed-bf05-0242c0a8d00a", "type": "Subscription", "subscriptionName": "Notify Test Yvonne", "description": "Test Yvonne externes Ziel", "entities": [ { "type": "Device" } ], "watchedAttributes": [ "dateObserved" ], "status": "active", "isActive": true, "notification": { "format": "normalized", "endpoint": { "uri": "https://nodered.staging.addix.io/yvonne", "accept": "application/json" }, "status": "ok" }, "origin": "cache" } ]

Docker Logs:

INFO@08:28:22 orionld.cpp[1065]: Orion Context Broker is running
TMP@08:28:22 orionld.cpp[765]: Version Info:
TMP@08:28:22 orionld.cpp[766]: -----------------------------------------
TMP@08:28:22 orionld.cpp[767]: orionld version: post-v1.1.0
TMP@08:28:22 orionld.cpp[768]: based on orion: 1.15.0-next
TMP@08:28:22 orionld.cpp[769]: git hash: nogitversion
TMP@08:28:22 orionld.cpp[770]: build branch:
TMP@08:28:22 orionld.cpp[771]: compiled by: root
TMP@08:28:22 orionld.cpp[772]: compiled in:
TMP@08:28:22 orionld.cpp[773]: -----------------------------------------
TMP@08:28:22 mongocInit.cpp[289]: Connecting to mongo for the C driver
DEBUG@08:28:22 urlParse.cpp[200]: URL: 'http://node-red:1880/notification'
DEBUG@08:28:22 urlParse.cpp[261]: Protocol: 'http'
DEBUG@08:28:22 urlParse.cpp[262]: Host: 'node-red'
DEBUG@08:28:22 urlParse.cpp[263]: Port: 1880
DEBUG@08:28:22 urlParse.cpp[264]: Path: 'notification'
DEBUG@08:28:22 subCacheApiSubscriptionInsert.cpp[275]: Sub 'urn:ngsi-ld:subscription:ce5211fc-b0fe-11ed-a7e7-0242c0a8900a'. protocol: 'http', IP: 'node-red', port: 1880, rest: 'notification'
INFO@08:28:22 orionld.cpp[1258]: Startup completed
TMP@08:28:22 orionld.cpp[1273]: Initialization is Done
TMP@08:28:22 orionld.cpp[1274]: Accepting REST requests on port 1026 (experimental API endpoints are enabled)
TMP@08:28:22 orionld.cpp[1275]: TRoE: Disabled
TMP@08:28:22 orionld.cpp[1276]: Distributed Operation: Disabled
TMP@08:28:22 orionld.cpp[1277]: Health Check: Disabled
TMP@08:28:22 orionld.cpp[1282]: Mongo Server Version: 6.0.4
TMP@08:28:22 orionld.cpp[1286]: Mongo Driver: mongoc driver
TMP@08:28:22 orionld.cpp[1287]: MongoC Driver Version: 1.22.0
TMP@08:28:22 orionld.cpp[1288]: The MongoDB C++ Legacy Driver is DISABLED - registration requests don't work in this mode
DEBUG@08:31:23 alteration.cpp[73]: Added alteration for entity 'urn:ngsi-ld:Device:NUCLEON:06000010006FF4F1'
DEBUG@08:31:23 orionldAlterationsTreat.cpp[210]: 1 items in matchList:
DEBUG@08:31:23 orionldAlterationsTreat.cpp[216]: o 1/1 Subscription 'urn:ngsi-ld:subscription:ce5211fc-b0fe-11ed-a7e7-0242c0a8900a'
DEBUG@08:31:23 httpNotify.cpp[43]: Connecting to notification 'node-red:1880' receptor for 'http' notification
DEBUG@08:31:23 httpNotify.cpp[53]: Connected to notification receptor 'node-red:1880' on fd 15
DEBUG@08:31:23 httpNotify.cpp[66]: Written 1899 bytes to fd 15 of node-red:1880 for sub urn:ngsi-ld:subscription:ce5211fc-b0fe-11ed-a7e7-0242c0a8900a
DEBUG@08:31:23 orionldAlterationsTreat.cpp[279]: notificationSend returned fd 15 (-2 is OK if HTTPS)
DEBUG@08:31:23 orionldAlterationsTreat.cpp[311]: No HTTPS notifications
DEBUG@08:31:23 alteration.cpp[73]: Added alteration for entity 'urn:ngsi-ld:WeatherObserved:NUCLEON:06000010006FF4F1'
DEBUG@08:31:34 urlParse.cpp[200]: URL: 'https://nodered.staging.addix.io/yvonne'
DEBUG@08:31:34 urlParse.cpp[261]: Protocol: 'https'
DEBUG@08:31:34 urlParse.cpp[262]: Host: 'nodered.staging.addix.io'
DEBUG@08:31:34 urlParse.cpp[263]: Port: 80
DEBUG@08:31:34 urlParse.cpp[264]: Path: 'yvonne'
DEBUG@08:31:34 subCacheApiSubscriptionInsert.cpp[275]: Sub 'urn:ngsi-ld:subscription:a592877a-b41d-11ed-bf05-0242c0a8d00a'. protocol: 'https', IP: 'nodered.staging.addix.io', port: 80, rest: 'yvonne'
DEBUG@08:46:29 alteration.cpp[73]: Added alteration for entity 'urn:ngsi-ld:Device:NUCLEON:06000010006FF4F1'
DEBUG@08:46:29 orionldAlterationsTreat.cpp[210]: 2 items in matchList:
DEBUG@08:46:29 orionldAlterationsTreat.cpp[216]: o 1/2 Subscription 'urn:ngsi-ld:subscription:a592877a-b41d-11ed-bf05-0242c0a8d00a'
DEBUG@08:46:29 orionldAlterationsTreat.cpp[216]: o 2/2 Subscription 'urn:ngsi-ld:subscription:ce5211fc-b0fe-11ed-a7e7-0242c0a8900a'
DEBUG@08:46:29 httpsNotify.cpp[98]: Protocol for HTTPS notification: https (2)
DEBUG@08:46:29 httpsNotify.cpp[99]: IP for HTTPS notification: nodered.staging.addix.io
DEBUG@08:46:29 httpsNotify.cpp[100]: Port for HTTPS notification: 80
DEBUG@08:46:29 httpsNotify.cpp[101]: Rest for HTTPS notification: yvonne
DEBUG@08:46:29 httpsNotify.cpp[134]: URL: https://nodered.staging.addix.io:80/yvonne
DEBUG@08:46:29 httpsNotify.cpp[166]: BODY: {"id":"urn:ngsi-ld:Notification:bb49b00a-b41f-11ed-a391-0242c0a8d00a","type":"Notification","subscriptionId":"urn:ngsi-ld:subscription:a592877a-b41d-11ed-bf05-0242c0a8d00a","notifiedAt":"2023-02-24T08:46:29.749Z","data":[{"id":"urn:ngsi-ld:Device:NUCLEON:06000010006FF4F1","type":"Device","dateFirstUsed":{"type":"Property","value":{"@type":"DateTime","@value":"2023-02-19T16:15:37.709Z"}},"controlledAsset":{"type":"Property","value":"urn:ngsi-ld:WeatherObserved:NUCLEON:06000010006FF4F1"},"location":{"type":"GeoProperty","value":{"type":"Point","coordinates":[9.410137,54.654365]}},"name":{"type":"Property","value":"LoRain 1"},"owner":{"type":"Property","value":"urn:ngsi-ld:Owner:NUCLEON"},"address":{"type":"Property","value":{"addressLocality":"Tarp","postalCode":"24963","streetAddress":"An der Alten Schule 3"}},"dateObserved":{"type":"Property","value":{"@type":"DateTime","@value":"2023-02-24T08:46:29.512Z"}},"batteryVoltage":{"type":"Property","value":2.7},"dateLastValueReported":{"type":"Property","value":{"@type":"DateTime","@value":"2023-02-24T08:46:29.512Z"}},"value":{"type":"Property","value":[{"parameter":"BatV","value":2.7},{"parameter":"BatVAlert1","value":2.9},{"parameter":"BatVAlert2","value":2.8},{"parameter":"ALARM","value":-1},{"parameter":"ALARM_TYPE","value":-1},{"parameter":"ALARM_VALUE","value":-1},{"parameter":"RAINLEVEL","value":0},{"parameter":"UPTIME","value":39},{"parameter":"port","value":10},{"parameter":"fcnt","value":3633}]}}]}
DEBUG@08:46:29 httpsNotify.cpp[180]: Added curl easy-handler to the multi-handler
DEBUG@08:46:29 orionldAlterationsTreat.cpp[279]: notificationSend returned fd -2 (-2 is OK if HTTPS)
DEBUG@08:46:29 httpNotify.cpp[43]: Connecting to notification 'node-red:1880' receptor for 'http' notification
DEBUG@08:46:29 httpNotify.cpp[53]: Connected to notification receptor 'node-red:1880' on fd 15
DEBUG@08:46:29 httpNotify.cpp[66]: Written 1899 bytes to fd 15 of node-red:1880 for sub urn:ngsi-ld:subscription:ce5211fc-b0fe-11ed-a7e7-0242c0a8900a
DEBUG@08:46:29 orionldAlterationsTreat.cpp[279]: notificationSend returned fd 15 (-2 is OK if HTTPS)
DEBUG@08:46:29 orionldAlterationsTreat.cpp[300]: Starting HTTPS notifications
DEBUG@08:46:29 orionldAlterationsTreat.cpp[308]: Started HTTPS notifications
DEBUG@08:46:29 alteration.cpp[73]: Added alteration for entity 'urn:ngsi-ld:WeatherObserved:NUCLEON:06000010006FF4F1'
DEBUG@08:46:34 orionldAlterationsTreat.cpp[405]: Awaiting HTTPS notification responses
DEBUG@08:46:34 orionldAlterationsTreat.cpp[420]: 0 HTTPS notifications are still active
DEBUG@08:46:34 orionldAlterationsTreat.cpp[452]: Notification Host: 'node-red'
DEBUG@08:46:34 orionldAlterationsTreat.cpp[453]: Notification Result for subscription 'urn:ngsi-ld:subscription:ce5211fc-b0fe-11ed-a7e7-0242c0a8900a': CURLcode 28 (Timeout was reached)
DEBUG@08:46:34 orionldAlterationsTreat.cpp[454]: Update Counters for subscription 'urn:ngsi-ld:subscription:ce5211fc-b0fe-11ed-a7e7-0242c0a8900a'

The http: endpoint received data

We have not tested this in the cluster yet, but it will not behave differently.

[kzangeli]

Looks pretty good.
The only error I can see is that the response for the HTTPS notificartion didn't reach the broker. It timed out - CURLcode 28 (Timeout was reached)

There's a "timesSent": 3 in the HTTP subscription, and both errors and successes.

It seems like the broker (my fault) is adding statistics amd timestamps to the wrong subscription!
The "curl error 28" belongs to the HTTPS subscription, not the HTTP one ...

I will look into that. Never mind the statistics for now. Might just confuse us.

Now, from what I can see, the HTTP notification went fine (I have no log messages about receiving the notification-response, unfortunately), while the HTTPS notification times out. The notification is sent, but no response comes back in time.
Can you confirm what I just stated ?

[DasNordlicht]

Yes http works and the data arrives at the destination.
HTTPS does not work and the data does not arrive at the destination.
The HTTPS destination is an http/2 destination.

[kzangeli]

So, I found and fixed a bug (it was an uninitialized variable making http notification ·"inherit" the curl handle from the previous https notification, and these curl handlkes are later used to look up the corresponding subscriptions to report the statistics).

I also improved the logging for http/https notifications.

New trace levels: 200-204.

Perhaps the better logging can shed some light on the problem with https notifications ...

[FR-ADDIX]

ok, I have now tested this with the last version.
HTTP: works
HTTPS: does not work
Statistik: works

why Port 80 by https ;-)
DEBUG@12:05:56 urlParse.cpp[200]: URL: 'https://nodered.staging.addix.io/yvonne'
DEBUG@12:05:56 urlParse.cpp[261]: Protocol: 'https'
DEBUG@12:05:56 urlParse.cpp[262]: Host: 'nodered.staging.addix.io'
DEBUG@12:05:56 urlParse.cpp[263]: Port: 80
DEBUG@12:05:56 urlParse.cpp[264]: Path: 'yvonne'

The target is reachable from the Orion LD container via HTTPS:

curl -v --location https://nodered.staging.addix.io/yvonne -d '{"id":"test"}' --header 'Content-Type: application/json'

• Trying 212.51.10.76...
• TCP_NODELAY set
• Connected to nodered.staging.addix.io (212.51.10.76) port 443 (#0)
• ALPN, offering h2
• ALPN, offering http/1.1
• successfully set certificate verify locations:
• CAfile: /etc/pki/tls/certs/ca-bundle.crt
  CApath: none
• TLSv1.3 (OUT), TLS handshake, Client hello (1):
• TLSv1.3 (IN), TLS handshake, Server hello (2):
• TLSv1.3 (IN), TLS handshake, [no content] (0):
• TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
• TLSv1.3 (IN), TLS handshake, [no content] (0):
• TLSv1.3 (IN), TLS handshake, Certificate (11):
• TLSv1.3 (IN), TLS handshake, [no content] (0):
• TLSv1.3 (IN), TLS handshake, CERT verify (15):
• TLSv1.3 (IN), TLS handshake, [no content] (0):
• TLSv1.3 (IN), TLS handshake, Finished (20):
• TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
• TLSv1.3 (OUT), TLS handshake, [no content] (0):
• TLSv1.3 (OUT), TLS handshake, Finished (20):
• SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
• ALPN, server accepted to use h2
• Server certificate:
• subject: CN=nodered.staging.addix.io
• start date: Feb 2 03:05:46 2023 GMT
• expire date: May 3 03:05:45 2023 GMT
• subjectAltName: host "nodered.staging.addix.io" matched cert's "nodered.staging.addix.io"
• issuer: C=US; O=Let's Encrypt; CN=R3
• SSL certificate verify ok.
• Using HTTP2, server supports multi-use
• Connection state changed (HTTP/2 confirmed)
• Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
• TLSv1.3 (OUT), TLS app data, [no content] (0):
• TLSv1.3 (OUT), TLS app data, [no content] (0):
• TLSv1.3 (OUT), TLS app data, [no content] (0):
• Using Stream ID: 1 (easy handle 0x563d6c632690)
• TLSv1.3 (OUT), TLS app data, [no content] (0):

POST /yvonne HTTP/2
Host: nodered.staging.addix.io
User-Agent: curl/7.61.1
Accept: /
Content-Type: application/json
Content-Length: 13

• TLSv1.3 (IN), TLS handshake, [no content] (0):
• TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
• TLSv1.3 (OUT), TLS app data, [no content] (0):
• We are completely uploaded and fine
• TLSv1.3 (IN), TLS app data, [no content] (0):
• Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
• TLSv1.3 (OUT), TLS app data, [no content] (0):
• TLSv1.3 (IN), TLS app data, [no content] (0):
• TLSv1.3 (IN), TLS app data, [no content] (0):
• TLSv1.3 (IN), TLS app data, [no content] (0):
  < HTTP/2 200
  < access-control-allow-origin: *
  < content-type: application/json; charset=utf-8
  < date: Sun, 26 Feb 2023 12:00:47 GMT
  < etag: W/"d-pb8+rBajJ8S9l96H90awzjld1kQ"
  < strict-transport-security: max-age=31536000; includeSubDomains; preload
  < vary: Accept-Encoding
  < x-content-type-options: nosniff
  < x-frame-options: DENY
  < x-powered-by: Express
  < x-xss-protection: 1; mode=block
  < content-length: 13
  <
• TLSv1.3 (IN), TLS app data, [no content] (0):
• Connection #0 to host nodered.staging.addix.io left intact
  {"id":"test"}

[kzangeli]

Arghh, I didn't think about http/https ...
If the port isn't specified, I just use 80 as default.
I'll look at http/https and use 443 as default if https.

Anyway, if you give the port, you fix that problem.
It will obviously not work on port 80.

So, try it by setting the port and let me know (just add :443 after the IP address)

[FR-ADDIX]

it Works:

[ { "id": "urn:ngsi-ld:subscription:ce5211fc-b0fe-11ed-a7e7-0242c0a8900a", "type": "Subscription", "subscriptionName": "Notify Device changed", "description": "Notification ein neuer Device entsteht", "entities": [ { "type": "Device" } ], "watchedAttributes": [ "dateObserved" ], "status": "active", "isActive": true, "notification": { "format": "normalized", "endpoint": { "uri": "http://node-red:1880/notification", "accept": "application/json" }, "status": "ok", "timesSent": 205, "lastNotification": "2023-02-26T17:32:13.459Z", "lastFailure": "2023-02-26T10:21:38.064Z", "lastSuccess": "2023-02-26T17:32:13.459Z" }, "origin": "cache" }, { "id": "urn:ngsi-ld:subscription:1d774a58-b5fb-11ed-8d1e-0242c0a8f00a", "type": "Subscription", "subscriptionName": "Notify Test Yvonne", "description": "Test Yvonne externes Ziel", "entities": [ { "type": "Device" } ], "watchedAttributes": [ "dateObserved" ], "status": "active", "isActive": true, "notification": { "format": "normalized", "endpoint": { "uri": "https://nodered.staging.addix.io:443/yvonne", "accept": "application/json" }, "status": "ok", "timesSent": 2, "lastNotification": "2023-02-26T17:32:13.459Z", "lastSuccess": "2023-02-26T17:32:13.459Z" }, "origin": "cache" } ]

[kzangeli]

ok, good!
I'll fix the 80/443 stupidity tomorrow.
Today I'm doing trace level fixes.
Those 200-204 I told you about are going to change. Will be 71-76 once I merge my next PR (Monday I guess).
The trace levels are (were) from 2013-2015 and not really in use anymore, so I removed them all and added new ones.

[FR-ADDIX]

We will then adopt the upcoming version into our cluster. Then we can continue testing with proper load ;-)

[FR-ADDIX]

What trace levels do we have available now, where did you document them, and how do we use them?
I think -logLevel DEBUG -t 22 is a trace level 22, right?

[kzangeli]

Yes, it's a comma-separated list and it supports ranges, e,g,:

-t 0-5,20-22,31,41-47     (+ -logLevel DEBUG)

The "numbers" are defined in a header file:
https://github.com/FIWARE/context.Orion-LD/blob/develop/src/lib/logMsg/traceLevels.h

[kzangeli]

This issue is fixed, right?
Can we close it?

[DasNordlicht]

Yes,is fixed