telefonicaid / lightweightm2m-iotagent

IoT Agent accepting COAP requests. Designed to be a bridge between the OMA Lightweight M2M protocol and the NGSI interface.
https://fiware-iotagent-lwm2m.rtfd.io/
GNU Affero General Public License v3.0
24 stars 31 forks source link

Code debug #100

Closed FRDavid closed 6 years ago

FRDavid commented 6 years ago

Hi,

I checked the last changes (inclusion of last version of iotagent-node-lib) using my custom static mapping configuration already working with previous versions.

When the IOTAgent receives the registration from the device, it raises the following error:

lvl=FATAL | corr=n/a | trans=n/a | op=n/a | msg=An unexpected exception has been raised. Ignoring: TypeError: callback is not a function

I wonder know if there is some way to obtain debug information from errors in a deeper way (stacktrace).

The error appears using both device provisioning or static configuration.

(using device provisioning and mongodb)

time=2017-11-22T08:23:41.581Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.COAPRouter | msg=Handling request with method [POST] on url [/rd?lwm2m=1.0&ep=HOP240ac4045c86&b=U&lt=40] with messageId [49353] time=2017-11-22T08:23:41.582Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.COAPUtils | msg=Extracting query parameters from request time=2017-11-22T08:23:41.582Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.COAPUtils | msg=Processing query [lwm2m=1.0&ep=HOP240ac4045c86&b=U&lt=40] time=2017-11-22T08:23:41.582Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.Registration | msg=Handling registration request time=2017-11-22T08:23:41.582Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.COAPUtils | msg=Checking for the existence of the following parameters [["ep"]] time=2017-11-22T08:23:41.583Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.Registration | msg=Storing the following device in the db: { "name": "HOP240ac4045c86", "lifetime": "40", "address": "188.214.241.72", "port": 62783, "creationDate": "2017-11-22T08:23:41.583Z" } time=2017-11-22T08:23:41.583Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.Registration | msg=Registered device [HOP240ac4045c86] with type [SmartSpot] time=2017-11-22T08:23:41.584Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.Registration | msg=Calling user handler for registration actions for device [HOP240ac4045c86] time=2017-11-22T08:23:41.585Z | lvl=DEBUG | corr=n/a | trans=n/a | op=IOTAgent.LWM2MHandlers | msg=Handling registration of the device time=2017-11-22T08:23:41.585Z | lvl=DEBUG | corr=n/a | trans=n/a | op=IoTAgentNGSI.MongoDBGroupRegister | msg=Looking for entity params ["resource","apikey"] time=2017-11-22T08:23:41.598Z | lvl=DEBUG | corr=n/a | trans=n/a | op=IoTAgentNGSI.MongoDBGroupRegister | msg=Device group for fields [["resource","apikey"]]not found. time=2017-11-22T08:23:41.598Z | lvl=DEBUG | corr=n/a | trans=n/a | op=IoTAgentNGSI.MongoDBDeviceRegister | msg=Looking for entity with id [HOP240ac4045c86]. time=2017-11-22T08:23:41.605Z | lvl=FATAL | corr=n/a | trans=n/a | op=n/a | msg=An unexpected exception has been raised. Ignoring: TypeError: callback is not a function

(using static configuration and mongodb)

time=2017-11-22T08:26:05.265Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.COAPRouter | msg=Handling request with method [POST] on url [/rd?lwm2m=1.0&ep=HOP240ac4045c86&b=U&lt=40] with messageId [49353] time=2017-11-22T08:26:05.266Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.COAPUtils | msg=Extracting query parameters from request time=2017-11-22T08:26:05.266Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.COAPUtils | msg=Processing query [lwm2m=1.0&ep=HOP240ac4045c86&b=U&lt=40] time=2017-11-22T08:26:05.266Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.Registration | msg=Handling registration request time=2017-11-22T08:26:05.267Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.COAPUtils | msg=Checking for the existence of the following parameters [["ep"]] time=2017-11-22T08:26:05.268Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.Registration | msg=Storing the following device in the db: { "name": "HOP240ac4045c86", "lifetime": "40", "address": "188.214.241.72", "port": 62917, "creationDate": "2017-11-22T08:26:05.267Z" } time=2017-11-22T08:26:05.268Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.Registration | msg=Registered device [HOP240ac4045c86] with type [SmartSpot] time=2017-11-22T08:26:05.268Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.Registration | msg=Calling user handler for registration actions for device [HOP240ac4045c86] time=2017-11-22T08:26:05.269Z | lvl=DEBUG | corr=n/a | trans=n/a | op=IOTAgent.LWM2MHandlers | msg=Handling registration of the device time=2017-11-22T08:26:05.269Z | lvl=DEBUG | corr=n/a | trans=n/a | op=IoTAgentNGSI.MongoDBGroupRegister | msg=Looking for entity params ["resource","apikey"] time=2017-11-22T08:26:05.282Z | lvl=DEBUG | corr=n/a | trans=n/a | op=IoTAgentNGSI.MongoDBGroupRegister | msg=Device group for fields [["resource","apikey"]]not found. time=2017-11-22T08:26:05.282Z | lvl=DEBUG | corr=n/a | trans=n/a | op=IoTAgentNGSI.MongoDBDeviceRegister | msg=Looking for entity with id [HOP240ac4045c86]. time=2017-11-22T08:26:05.285Z | lvl=DEBUG | corr=n/a | trans=n/a | op=IoTAgentNGSI.MongoDBDeviceRegister | msg=Entity [HOP240ac4045c86] not found. time=2017-11-22T08:26:05.286Z | lvl=FATAL | corr=n/a | trans=n/a | op=n/a | msg=An unexpected exception has been raised. Ignoring: TypeError: callback is not a function

I didn't test with memory storage.

dcalvoalonso commented 6 years ago

@FRDavid , could you please post the example of the device that you are trying to provision? I will try to find where is the problem.

carloslucenah commented 6 years ago

Same problem here.

It appears when executing a "connect" command from the client.

For example:

POST http://localhost:4041/iot/devices

POST data:
 { "devices": [
      {
        "device_id": "robot3",
        "entity_type": "Device",
        "attributes": [
          {
            "name": "Battery",
            "type": "number"
          }
        ],
        "lazy": [
          {
            "name": "Message",
            "type": "string"
          }
        ],
        "commands": [
          {
            "name": "Position",
            "type": "location"
          }
        ],
      "internal_attributes": {
        "lwm2mResourceMapping": {
          "Battery" : {
            "objectType": 7393,
            "objectInstance": 0,
            "objectResource": 1
          },
          "Message" : {
            "objectType": 7393,
            "objectInstance": 0,
            "objectResource": 2
          },
          "Position" : {
            "objectType": 7393,
            "objectInstance": 0,
            "objectResource": 3
          }
        }
      }
    }
  ]
}

[no cookies]

Cabeceras de petición:
Connection: keep-alive
Content-Type: application/json
Fiware-Service: Factory
Fiware-ServicePath: /robots
Accept: application/json
Content-Length: 979
Host: localhost:4041
User-Agent: Apache-HttpClient/4.2.6 (java 1.5)

All OK

LWM2M-Client> create /7393/0

Object:
--------------------------------
ObjectType: 7393
ObjectId: 0
ObjectUri: /7393/0
LWM2M-Client> set /7393/0 1 6969

Object:

ObjectType: 7393 ObjectId: 0 ObjectUri: /7393/0

Attributes: -> 1: 6969


- Step 4: Trying to connect to the agent

LWM2M-Client> connect localhost 5684 robot3 /

Connecting to the server. This may take a while.

LWM2M-Client>

It never shows a "connected succesfully" message. In fact, after 247 seconds, a timeout message araises.

The agent log shows this:

time=2017-12-21T12:22:51.887Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.COAPRouter | msg=Handling request with method [POST] on url [/rd?ep=robot3&lt=85671&lwm2m=1.0&b=U] with messageId [29525] time=2017-12-21T12:22:51.887Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.COAPUtils | msg=Extracting query parameters from request time=2017-12-21T12:22:51.887Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.COAPUtils | msg=Processing query [ep=robot3&lt=85671&lwm2m=1.0&b=U] time=2017-12-21T12:22:51.887Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.Registration | msg=Handling registration request time=2017-12-21T12:22:51.887Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.COAPUtils | msg=Checking for the existence of the following parameters [["ep"]] time=2017-12-21T12:22:51.887Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.Registration | msg=Storing the following device in the db: { "name": "robot3", "lifetime": "85671", "address": "127.0.0.1", "port": 55447, "creationDate": "2017-12-21T12:22:51.887Z" } time=2017-12-21T12:22:51.888Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.Registration | msg=Registered device [robot3] with type [Device] time=2017-12-21T12:22:51.888Z | lvl=DEBUG | corr=n/a | trans=n/a | op=LWM2MLib.Registration | msg=Calling user handler for registration actions for device [robot3] time=2017-12-21T12:22:51.888Z | lvl=DEBUG | corr=n/a | trans=n/a | op=IOTAgent.LWM2MHandlers | msg=Handling registration of the device time=2017-12-21T12:22:51.888Z | lvl=DEBUG | corr=n/a | trans=n/a | op=IoTAgentNGSI.MongoDBGroupRegister | msg=Looking for entity params ["resource","apikey"] time=2017-12-21T12:22:51.889Z | lvl=DEBUG | corr=n/a | trans=n/a | op=IoTAgentNGSI.MongoDBGroupRegister | msg=Device group for fields [["resource","apikey"]]not found. time=2017-12-21T12:22:51.889Z | lvl=DEBUG | corr=n/a | trans=n/a | op=IoTAgentNGSI.MongoDBDeviceRegister | msg=Looking for entity with id [robot3]. time=2017-12-21T12:22:51.892Z | lvl=FATAL | corr=n/a | trans=n/a | op=n/a | msg=An unexpected exception has been raised. Ignoring: TypeError: callback is not a function



Tested with docker Orion versions 0.26 and latest version. Mongodb docker version and non-docker versions, 3.2 and latest versions. Always the same result.

Thanks in advance.
dcalvoalonso commented 6 years ago

This should be fixed once https://github.com/telefonicaid/lightweightm2m-iotagent/pull/105 is merged.

fgalan commented 6 years ago

This issue should be fixed by PR https://github.com/telefonicaid/lightweightm2m-iotagent/pull/105. Now that this PR has been merged into master, @FRDavid could you please confirm is ok so this issue can be closed? Thanks!

carloslucenah commented 6 years ago

Tested after the merge.

Client log:

LWM2M-Client> connect localhost 5684 robot4 /

Connecting to the server. This may take a while.

LWM2M-Client> time=2017-12-22T10:23:19.801Z | lvl=INFO | corr=n/a | trans=n/a | op=LWM2MLib.COAPRouter | msg=Starting COAP Server on port [46474]
time=2017-12-22T10:23:19.803Z | lvl=INFO | corr=n/a | trans=n/a | op=LWM2MLib.COAPRouter | msg=COAP Server started successfully

Connected:
--------------------------------
Device location: rd/3
LWM2M-Client>

Agent log:

time=2017-12-22T10:23:19.782Z | lvl=DEBUG | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.MongoDBGroupRegister | srv=n/a | subsrv=n/a | msg=Looking for entity params ["resource","apikey"] | comp=IoTAgent
time=2017-12-22T10:23:19.784Z | lvl=DEBUG | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.MongoDBGroupRegister | srv=n/a | subsrv=n/a | msg=Device group for fields [["resource","apikey"]] not found: [{}] | comp=IoTAgent
time=2017-12-22T10:23:19.784Z | lvl=DEBUG | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.MongoDBDeviceRegister | srv=n/a | subsrv=n/a | msg=Looking for entity with id [robot4]. | comp=IoTAgent
time=2017-12-22T10:23:19.785Z | lvl=DEBUG | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.MongoDBDeviceRegister | srv=n/a | subsrv=n/a | msg=Entity [robot4] not found. | comp=IoTAgent
{"op":"IOTAgent.LWM2MHandlers","time":"2017-12-22T10:23:19.785Z","lvl":"DEBUG","msg":"Device register not found. Creating new device."}
{"op":"IOTAgent.LWM2MHandlers","time":"2017-12-22T10:23:19.786Z","lvl":"DEBUG","msg":"Mapping device found to NGSI register"}
time=2017-12-22T10:23:19.786Z | lvl=DEBUG | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.MongoDBDeviceRegister | srv=n/a | subsrv=n/a | msg=Looking for entity with id [robot4]. | comp=IoTAgent
time=2017-12-22T10:23:19.787Z | lvl=DEBUG | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.MongoDBDeviceRegister | srv=n/a | subsrv=n/a | msg=Entity [robot4] not found. | comp=IoTAgent
time=2017-12-22T10:23:19.787Z | lvl=DEBUG | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.MongoDBGroupRegister | srv=n/a | subsrv=n/a | msg=Looking for entity params undefined | comp=IoTAgent
time=2017-12-22T10:23:19.788Z | lvl=DEBUG | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.MongoDBGroupRegister | srv=n/a | subsrv=n/a | msg=Device group for fields [undefined] not found: [{"undefined":"Device"}] | comp=IoTAgent
time=2017-12-22T10:23:19.788Z | lvl=DEBUG | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.DeviceService | srv=n/a | subsrv=n/a | msg=Registering device into NGSI Service:
{
    "id": "robot4",
    "name": "robot4:Device",
    "type": "Device",
    "service": "smartGondor",
    "subservice": "/gardens",
    "lazy": [],
    "commands": [],
    "internalId": 3,
    "active": null,
    "staticAttributes": [],
    "subscriptions": []
} | comp=IoTAgent
time=2017-12-22T10:23:19.789Z | lvl=DEBUG | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.DeviceService | srv=n/a | subsrv=n/a | msg=No Context Provider registrations found for unregister | comp=IoTAgent
time=2017-12-22T10:23:19.789Z | lvl=DEBUG | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.DeviceService | srv=n/a | subsrv=n/a | msg=Creating initial entity in the Context Broker:
 {
    "url": "http://localhost:1026/v1/updateContext",
    "method": "POST",
    "json": {
        "contextElements": [
            {
                "type": "Device",
                "isPattern": "false",
                "id": "robot4:Device",
                "attributes": []
            }
        ],
        "updateAction": "APPEND"
    },
    "headers": {
        "fiware-service": "smartGondor",
        "fiware-servicepath": "/gardens",
        "fiware-correlator": "7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0"
    }
} | comp=IoTAgent
time=2017-12-22T10:23:19.794Z | lvl=DEBUG | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.DeviceService | srv=n/a | subsrv=n/a | msg=Initial entity created successfully. | comp=IoTAgent
time=2017-12-22T10:23:19.795Z | lvl=DEBUG | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.MongoDBDeviceRegister | srv=n/a | subsrv=n/a | msg=Storing device with id [robot4] and type [Device] | comp=IoTAgent
time=2017-12-22T10:23:19.798Z | lvl=ERROR | corr=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | trans=7db3eb34-e2ae-4c76-bb63-a69a5a1d1ad0 | op=IoTAgentNGSI.Alarms | srv=n/a | subsrv=n/a | msg=Releasing [MONGO-ALARM] | comp=IoTAgent
{"op":"LWM2MLib.Registration","time":"2017-12-22T10:23:19.798Z","lvl":"DEBUG","msg":"Registration request ended successfully"}
{"time":"2017-12-22T10:23:19.848Z","lvl":"DEBUG","msg":"Observers created successfully."}

The error has gone :)

fgalan commented 6 years ago

Thanks for the feedback! Closing

arilwan commented 6 years ago

Hi Daniel,

I am having this same problem please. May I know how to figure it out please. Timeout message raised after 247 seconds.

Thank you

fgalan commented 6 years ago

I am having this same problem please.

Is the one already reported at https://github.com/telefonicaid/lightweightm2m-iotagent/issues/114#issuecomment-422329193 or a different one?

arilwan commented 6 years ago

Yes, it is.

Many thanks,

Akil

On Tue, Sep 18, 2018 at 12:24 PM Fermín Galán Márquez < notifications@github.com> wrote:

I am having this same problem please.

Is the one already reported at #114 (comment) https://github.com/telefonicaid/lightweightm2m-iotagent/issues/114#issuecomment-422329193 or a different one?

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/telefonicaid/lightweightm2m-iotagent/issues/100#issuecomment-422355819, or mute the thread https://github.com/notifications/unsubscribe-auth/Aocds71SAcsHVqOQxgUbGcT5S85BXdEuks5ucNfSgaJpZM4QpvIu .

fgalan commented 6 years ago

Ok. Let's continue dicussion in #114.