MQTT Notification raise "curl_easy_perform failed: Timeout was reached" #1178

walterwootz · 2022-07-11T08:01:06Z

Hi everyone,

I'm trying to receive Orion LD notifications using mqtt protocol which instead work well with Orion v2.

The error is the following:

time=Friday 08 Jul 14:42:43 2022.769Z | lvl=ERROR | corr=N/A | trans=1657291349-662-00000000001 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=httpRequestSend.cpp[573]:httpRequestSendWithCurl | msg=curl_easy_perform failed: 28

time=Friday 08 Jul 14:42:43 2022.769Z | lvl=WARN | corr=N/A | trans=1657291349-662-00000000001 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=AlarmManager.cpp[338]:notificationError | 
msg=Raising alarm NotificationError mqtt//mosquitto:1883/example_mosquitto_topic?subscriptionId=urn:ngsi-ld:Subscription:329e3c8e-fecc-11ec-92f9-0242c0a8500d: (curl_easy_perform failed: Timeout was reached)

Orion is launched using a docker-compose together with an instance of mosquitto where mqtt notifications should be sent. Consider that the subscription using the json below is successfull.

docker-compose.yaml

   orion:
    hostname: orion
    image: fiware/orion-ld:latest
    networks:
      - hostnet
    ports:
      - "1026:1026"
    depends_on:
      - mongodb
      - mosquitto
    # add -forwarding if using NGSI-ld
    command: -statCounters -dbhost mongodb -logLevel DEBUG -forwarding
    environment:
       - IOTA_JSON_LD_CONTEXT=https://uri.etsi.org/ngsi-ld/v1/ngsi-ld-core-context.jsonld #comment if you mind using NGSIv2

  mongodb:
    hostname: mongodb
    image: mongo:4.2
    networks:
      - hostnet
    ports:
      - "27017:27017"
    volumes:
      - mongo_data_volume:/data/db
      - mongo_conf_volume:/data/configdb
    command: --nojournal

  mosquitto:
    image: eclipse-mosquitto
    hostname: mosquitto
    networks:
      - hostnet
    ports:
      - 1883:1883
      - 9001:9001
    volumes:
      - ./conf/mosquitto/mosquitto.conf:/mosquitto/config/mosquitto.conf
      - mosquitto_volume:/mosquitto/data

volumes:
  mongo_data_volume:
  mongo_conf_volume:
  mosquitto_volume:

json subscription request

{
  "type": "Subscription",
  "name": "Car-Subscription",
  "description": "Car subscription",
  "entities": [
    {
      "id": "urn:ngsi-ld:Device:age01_Car",
      "type": "Device"
    }
  ],
  "watchedAttributes": [
    "Engine_Oxigen",
    "Engine_Temperature"
  ],
  "notification": {
    "attributes": [
      "Engine_Oxigen",
      "Engine_Temperature"
    ],
    "format": "keyValues",
    "endpoint": {
      "uri": "mqtt://mosquitto:1883/example_mosquitto_topic"
    }
  },
  "@context": "https://uri.etsi.org/ngsi-ld/v1/ngsi-ld-core-context.jsonld"
}

The error seems to be raised on function httpRequestSendWithCurl in httpRequestSend.cpp (it's just a guess, no debugging has been done). Maybe the url is not recognized correctly as mqtt? Or something is wrong on the subscription request object?

Thank you!

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

kzangeli · 2022-07-11T13:03:08Z

Hi, thanks for reporting.
I will look into this, I'd say asap, but, unfortunately I have a business meeting from tomorrow morning until Thursday evening, which will keep me quite busy ...
Promise to do my best though.

kzangeli · 2022-07-17T23:01:18Z

So, finally got some time ...
I tried your exact subscription and it worked just fine (had to invent a matching entity) - the notification arrived via MQTT.
BUT, what you said about httpRequestSendWithCurl() is 100% correct, it seems like the broker in your case doesn't understand it is to use the protocol "mqtt", which is quite weird.

You should see something like this in the broker log:

QueueWorkers.cpp[129]:workerFunc : worker sending 'mqtt' message to: host='localhost', port=1883, verb=POST, tenant='', service-path: '', xauthToken: '', path='example_mosquitto_topic', content-type: application/json

And definitely not what you see - unless you have another matching subscription using "http" of course.
Not that I really think so, it's just weird that the broker understands it as HTTP and not MQTT.

So, can you tell me something else about your case?
Cause, I have nothing to go on right now, to understand the issue.

walterwootz · 2022-07-20T13:34:04Z

Hi @kzangeli thank you for your kind reply.

In Orion there is only one subscription and only one entity, listed below:

GET http://localhost:1026/ngsi-ld/v1/subscriptions

[
    {
        "id": "urn:ngsi-ld:Subscription:8df0036e-082d-11ed-99ad-0242c0a8500d",
        "type": "Subscription",
        "subscriptionName": "Car-Subscription",
        "description": "Car subscription",
        "entities": [
            {
                "id": "urn:ngsi-ld:Device:age01_Car",
                "type": "Device"
            }
        ],
        "watchedAttributes": [
            "Engine_Oxigen",
            "Engine_Temperature"
        ],
        "status": "active",
        "isActive": true,
        "notification": {
            "attributes": [
                "Engine_Oxigen",
                "Engine_Temperature"
            ],
            "format": "keyValues",
            "endpoint": {
                "uri": "mqtt://mosquitto:1883/example_mosquitto_topic",
                "accept": "application/json"
            },
            "status": "ok",
            "timesSent": 3,
            "lastNotification": "2022-07-20T13:14:05.381Z"
        },
        "@context": "https://uri.etsi.org/ngsi-ld/v1/ngsi-ld-core-context.jsonld"
    }
]

In mongodb I have only one entity:

[
    {
        "id": "urn:ngsi-ld:Device:age01_Car",
        "type": "Device",
        "Accelerate_info": {
            "type": "Property",
            "value": {
                "@type": "commandResult",
                "@value": " "
            }
        },
        "Accelerate_status": {
            "type": "Property",
            "value": {
                "@type": "commandStatus",
                "@value": "UNKNOWN"
            }
        },
        "Acceleration": {
            "type": "Property",
            "value": 0
        },
        "EngineStopped": {
            "type": "Property",
            "value": true
        },
        "Engine_Oxigen": {
            "type": "Property",
            "value": 219
        },
        "Engine_Temperature": {
            "type": "Property",
            "value": 20
        },
        "Error_info": {
            "type": "Property",
            "value": {
                "@type": "commandResult",
                "@value": " "
            }
        },
        "Error_status": {
            "type": "Property",
            "value": {
                "@type": "commandStatus",
                "@value": "UNKNOWN"
            }
        },
        "Stop_info": {
            "type": "Property",
            "value": {
                "@type": "commandResult",
                "@value": " "
            }
        },
        "Stop_status": {
            "type": "Property",
            "value": {
                "@type": "commandStatus",
                "@value": "UNKNOWN"
            }
        }
    }
]

I was thinking, may that the problem come from the way I update the attribute?
In my app I am updating an attribute using the following PATCH call (the same used with http and the notification works pretty well):
curl --location --request PATCH 'http://localhost:1026/ngsi-ld/v1/entities/urn:ngsi-ld:Device:age01_Car/attrs' --header 'Content-Type: application/json' --data-raw '{ "Engine_Oxigen": { "type": "Property", "value": 220 } }'

Another reason could be the way I am running Orion LD? Is the docker-compose in the first message complete? Maybe something is wrong or is missing?

kzangeli · 2022-07-20T13:56:27Z

ok, I'll try that PATCH. Open to anything right now :)

walterwootz · 2022-07-20T14:00:36Z

Here is also the complete subscription request:

curl --location --request POST 'http://localhost:1026/ngsi-ld/v1/subscriptions' \
--header 'Accept: application/json' --header \
'Content-Type: application/ld+json' --data-raw '{
  "type": "Subscription",
  "name": "Car-Subscription",
  "description": "Car subscription",
  "entities": [
    {
      "id": "urn:ngsi-ld:Device:age01_Car",
      "type": "Device"
    }
  ],
  "watchedAttributes": [
    "Engine_Oxigen",
    "Engine_Temperature"
  ],
  "notification": {
    "attributes": [
      "Engine_Oxigen",
      "Engine_Temperature"
    ],
    "format": "keyValues",
    "endpoint": {
      "uri": "mqtt://mosquitto:1883/example_mosquitto_topic"
    }
  },
  "@context": "https://uri.etsi.org/ngsi-ld/v1/ngsi-ld-core-context.jsonld"
}'

I have launched Orion in DEBUG and here is the complete log when updating attribute:

time=Wednesday 20 Jul 13:53:48 2022.137Z | lvl=TMP | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=orionldMhdConnectionInit.cpp[927]:orionldMhdConnectionInit | msg=------------------------- Servicing NGSI-LD request 020: PATCH /ngsi-ld/v1/entities/urn:ngsi-ld:Device:age01_Car/attrs --------------------------
time=Wednesday 20 Jul 13:53:48 2022.138Z | lvl=TMP | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=kjTreeLog.cpp[64]:kjTreeLogFunction | msg=/opt/orion/src/lib/orionld/payloadCheck/pCheckAttribute.cpp[950]: GEO: Looping over all attribute fields: {"type":"Property","value":228}
time=Wednesday 20 Jul 13:53:48 2022.138Z | lvl=TMP | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=kjTreeLog.cpp[64]:kjTreeLogFunction | msg=/opt/orion/src/lib/orionld/payloadCheck/pCheckAttribute.cpp[1060]: GEO: attr after: {"type":"Property","value":228}
time=Wednesday 20 Jul 13:53:48 2022.139Z | lvl=TMP | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=kjTreeFromContextAttribute.cpp[148]:kjTreeFromContextAttribute | msg=LANG: Attribute: 'https://uri.etsi.org/ngsi-ld/default-context/Engine_Oxigen', type: 'Property', lang at: '(nil)'
time=Wednesday 20 Jul 13:53:48 2022.139Z | lvl=TMP | corr=N/A | trans=N/A | from=N/A | srv=N/A | subsrv=N/A | comp=Orion | op=kjTreeFromContextAttribute.cpp[148]:kjTreeFromContextAttribute | msg=LANG: Attribute: 'https://uri.etsi.org/ngsi-ld/default-context/Engine_Temperature', type: 'Property', lang at: '(nil)'
time=Wednesday 20 Jul 13:53:48 2022.139Z | lvl=TMP | corr=N/A | trans=1658324630-383-00000000008 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=httpRequestSend.cpp[564]:httpRequestSendWithCurl | msg=Sending message 8 to HTTP server: sending message of 690 bytes to HTTP server
time=Wednesday 20 Jul 13:53:58 2022.145Z | lvl=ERROR | corr=N/A | trans=1658324630-383-00000000008 | from=pending | srv=pending | subsrv=pending | comp=Orion | op=httpRequestSend.cpp[573]:httpRequestSendWithCurl | msg=curl_easy_perform failed: 28

kzangeli · 2022-07-20T14:18:20Z

ok, perfect

kzangeli · 2022-07-20T21:12:22Z

So, I created a functional test, as close as I could to your "case".
Unfortunately, it worked just fine, I'm not able to reproduce the error you're getting:
#1188

Take a look at the PR - it's just a functional test.
I believe the test file is quite simple to understand:

What's between --SHELL-INIT-- and --SHELL is executed to prepare for the test to run
What's between --SHELL- and --REGEXPECT-- is executed - this is the TEST
What's between --REGEXPECT-- and --TEARDOWN-- is the expected outcome (on stdout) of the TEST.

Finally the real outcome on stdout is compared to "the expected outcome" and if it's the same, then the test worked.

orionCurl is a shell function I implemented to make it a little easier to write test cases - it's basically a call to curl.

Now, look closely at the --SHELL-- section and propose changes to the test - see if we can make me able to reproduce the error you are seeing.

Alternatively, modify your own stuff to be closer to my test file content and perhaps your error goes away.

Good luck (to both of us :)) !

walterwootz · 2022-07-21T15:07:42Z

@kzangeli the functional test fit exactly my use case.

I launched the following shell script inside orion container that should be the same as your functional test script:

echo "01. Create an entity age01_Car, to later be patched to match S1"
echo "==============================================================="
payload='{
  "id": "urn:ngsi-ld:Device:age01_Car",
  "type": "Device",
  "Accelerate_info": {
    "type": "Property",
    "value": {
    }
  },
  "Accelerate_status": {
    "type": "Property",
    "value": {
      "@type": "commandStatus",
      "@value": "UNKNOWN"
    }
  },
  "Acceleration": {
    "type": "Property",
    "value": 0
  },
  "EngineStopped": {
    "type": "Property",
    "value": true
  },
  "Engine_Oxigen": {
    "type": "Property",
    "value": 219
  },
  "Engine_Temperature": {
    "type": "Property",
    "value": 20
  },
  "Error_info": {
    "type": "Property",
    "value": {
      "@type": "commandResult",
      "@value": " "
    }
  },
  "Error_status": {
    "type": "Property",
    "value": {
      "@type": "commandStatus",
      "@value": "UNKNOWN"
    }
  },
  "Stop_info": {
    "type": "Property",
    "value": {
      "@type": "commandResult",
      "@value": " "
    }
  },
  "Stop_status": {
    "type": "Property",
    "value": {
      "@type": "commandStatus",
      "@value": "UNKNOWN"
    }
  }
}'
curl -H 'Content-Type: application/json' --url http://localhost:1026/ngsi-ld/v1/entities -d "$payload"
echo
echo


echo "02. Create subscription S1 with MQTT broker as endpoint"
echo "======================================================="
payload='{
  "id": "urn:ngsi-ld:subscription:S1",
  "type": "Subscription",
  "name": "Car-Subscription",
  "description": "Car subscription",
  "entities": [
    {
      "id": "urn:ngsi-ld:Device:age01_Car",
      "type": "Device"
    }
  ],
  "watchedAttributes": [
    "Engine_Oxigen",
    "Engine_Temperature"
  ],
  "notification": {
    "attributes": [
      "Engine_Oxigen",
      "Engine_Temperature"
    ],
    "format": "keyValues",
    "endpoint": {
      "uri": "mqtt://mosquitto:1883/example_mosquitto_topic"
    }
  }
}'
curl -H 'Content-Type: application/json' --url http://localhost:1026/ngsi-ld/v1/subscriptions -d "$payload"
echo
echo


echo "03. PATCH E1 to match S1"
echo "========================"
payload='{
  "Engine_Oxigen": {
    "type": "Property",
    "value": 220
  }
}'
curl -H 'Content-Type: application/json' --url http://localhost:1026/ngsi-ld/v1/entities/urn:ngsi-ld:Device:age01_Car/attrs -d "$payload" -X PATCH
echo
echo

All the 3 steps return response as expected, but the error is the same: orion is trying to send notification through http.
Does orionCurl do anything more than my curl test? If not, the problem is not on the requests but maybe on the environment...

Which version of Orion-LD are you using for your test? Are you passing some specific parameters?

kzangeli · 2022-07-21T15:21:27Z

ok, that's a good test.
But no, no magic involved. orionCurl just helps with visualizing HTTP headers and stuff like that.
I'm running on the latest - a branch taken from the "develop" branch.
Brand new - very much like you, from what I can see in your docker compose file (image: fiware/orion-ld:latest).
So, still quite weird ...
I think I'll have to add some temporary traces, see if we can understand what's happening.

kzangeli · 2022-07-21T15:24:55Z

Meanwhile, just to test ...
Add the CLI -experimental to the broker, see what happens (as the name says, it's experimental)

kzangeli · 2022-07-22T15:11:22Z

FYI:
I'm preparing a new release. Part of the preparation is to remove all temporary traces, including, of course, those new ones about MQTT.
This tag on dockerhub contains the traces: 1.1.0-PRE-993.
The next one will not have them anymore.

kzangeli · 2022-07-29T09:29:00Z

After a lot of debugging we've finally found the reason of this error.

MQTT notifications are implemented only for the case that the notificationMode is set to "threadpool".

I will implement the MQTT notifications also for the transient/persistent notificationMode, but for now, you'll just have to start the broker with the threadpool turned on:

-notificationMode threadpool

Note that you can set also the size of the queue and the number of threads with -notificationMode:

-notificationMode threadpool:10:20

Would give a queue size of 10 and 20 threads in the pool.
Default is:

queue size: 100
threads: 10

kzangeli self-assigned this Jul 11, 2022

kzangeli added the bug Something isn't working label Jul 11, 2022

kzangeli mentioned this issue Jul 12, 2022

Planning #280

Open

kzangeli added the Need more input label Jul 17, 2022

kzangeli removed the Need more input label Jul 20, 2022

kzangeli mentioned this issue Jul 20, 2022

Functest for issue 1178 #1188

Merged

kzangeli added a commit that referenced this issue Jul 28, 2022

Traces for issue #1178

a868c2d

kzangeli closed this as completed Aug 2, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

MQTT Notification raise "curl_easy_perform failed: Timeout was reached" #1178

MQTT Notification raise "curl_easy_perform failed: Timeout was reached" #1178

walterwootz commented Jul 11, 2022

kzangeli commented Jul 11, 2022

kzangeli commented Jul 17, 2022

walterwootz commented Jul 20, 2022

kzangeli commented Jul 20, 2022 •

edited

walterwootz commented Jul 20, 2022

kzangeli commented Jul 20, 2022

kzangeli commented Jul 20, 2022 •

edited

walterwootz commented Jul 21, 2022

kzangeli commented Jul 21, 2022

kzangeli commented Jul 21, 2022

kzangeli commented Jul 22, 2022 •

edited

kzangeli commented Jul 29, 2022

MQTT Notification raise "curl_easy_perform failed: Timeout was reached" #1178

MQTT Notification raise "curl_easy_perform failed: Timeout was reached" #1178

Comments

walterwootz commented Jul 11, 2022

kzangeli commented Jul 11, 2022

kzangeli commented Jul 17, 2022

walterwootz commented Jul 20, 2022

kzangeli commented Jul 20, 2022 • edited

walterwootz commented Jul 20, 2022

kzangeli commented Jul 20, 2022

kzangeli commented Jul 20, 2022 • edited

walterwootz commented Jul 21, 2022

kzangeli commented Jul 21, 2022

kzangeli commented Jul 21, 2022

kzangeli commented Jul 22, 2022 • edited

kzangeli commented Jul 29, 2022

kzangeli commented Jul 20, 2022 •

edited

kzangeli commented Jul 20, 2022 •

edited

kzangeli commented Jul 22, 2022 •

edited