Code debug #100

FRDavid · 2017-11-24T12:03:17Z

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 · 2017-11-28T10:47:01Z

@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 · 2017-12-21T13:18:51Z

Same problem here.

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

For example:

Step 1: Provisioning the device:

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

Step 2: Creating the object in the client console

LWM2M-Client> create /7393/0

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

Step 3: Updating an attribute value

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 · 2017-12-21T13:27:17Z

This should be fixed once #105 is merged.

fgalan · 2017-12-22T10:13:25Z

This issue should be fixed by PR #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 · 2017-12-22T10:25:58Z

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 · 2017-12-22T10:26:42Z

Thanks for the feedback! Closing

arilwan · 2018-09-17T16:00:52Z

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 · 2018-09-18T11:24:01Z

I am having this same problem please.

Is the one already reported at #114 (comment) or a different one?

arilwan · 2018-09-18T11:26:58Z

Yes, it is. Many thanks, Akil

…

On Tue, Sep 18, 2018 at 12:24 PM Fermín Galán Márquez < ***@***.***> wrote: I am having this same problem please. Is the one already reported at #114 (comment) <#114 (comment)> or a different one? — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#100 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/Aocds71SAcsHVqOQxgUbGcT5S85BXdEuks5ucNfSgaJpZM4QpvIu> .

fgalan · 2018-09-18T11:27:45Z

Ok. Let's continue dicussion in #114.

fgalan mentioned this issue Dec 20, 2017

Task/travis ci #105

Merged

fgalan closed this as completed Dec 22, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Code debug #100

Code debug #100

FRDavid commented Nov 24, 2017

dcalvoalonso commented Nov 28, 2017

carloslucenah commented Dec 21, 2017

dcalvoalonso commented Dec 21, 2017

fgalan commented Dec 22, 2017

carloslucenah commented Dec 22, 2017

fgalan commented Dec 22, 2017

arilwan commented Sep 17, 2018 •

edited

Loading

fgalan commented Sep 18, 2018

arilwan commented Sep 18, 2018 via email

fgalan commented Sep 18, 2018

Code debug #100

Code debug #100

Comments

FRDavid commented Nov 24, 2017

dcalvoalonso commented Nov 28, 2017

carloslucenah commented Dec 21, 2017

dcalvoalonso commented Dec 21, 2017

fgalan commented Dec 22, 2017

carloslucenah commented Dec 22, 2017

fgalan commented Dec 22, 2017

arilwan commented Sep 17, 2018 • edited Loading

fgalan commented Sep 18, 2018

arilwan commented Sep 18, 2018 via email

fgalan commented Sep 18, 2018

arilwan commented Sep 17, 2018 •

edited

Loading