telefonicaid / telefonicaid/iotagent-node-lib

First Connection Attempt to MongoDB always fails

Open
#986 2 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
JavaScript
Stars
62
Forks
90
Avg merge
2h 35m
Merged PRs (30d)
1

Description

Every time I try to start the Sigfox IoT Agent the attempt of the Agent to connect to MongoDB fails. Only then, it automatically tries to reconnect after 5 seconds with success.

DEBUG log below:

time=2021-02-03T17:02:30.956Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.Global | from=n/a | srv=n/a | subsrv=n/a | msg=Starting an IoT Agent... | comp=IoTAgent
time=2021-02-03T17:02:30.958Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentSIGFOX.SigfoxServer | from=n/a | srv=n/a | subsrv=n/a | msg=Starting Sigfox server listening on port [17428] | comp=IoTAgent
(node:3036) Warning: Accessing non-existent property 'count' of module exports inside circular dependency
(Use `node --trace-warnings ...` to show where the warning was created)
(node:3036) Warning: Accessing non-existent property 'findOne' of module exports inside circular dependency
(node:3036) Warning: Accessing non-existent property 'remove' of module exports inside circular dependency
(node:3036) Warning: Accessing non-existent property 'updateOne' of module exports inside circular dependency
(node:3036) Warning: Accessing non-existent property 'count' of module exports inside circular dependency
(node:3036) Warning: Accessing non-existent property 'findOne' of module exports inside circular dependency
(node:3036) Warning: Accessing non-existent property 'remove' of module exports inside circular dependency
(node:3036) Warning: Accessing non-existent property 'updateOne' of module exports inside circular dependency
time=2021-02-03T17:02:30.964Z | lvl=WARN | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.Global | from=n/a | srv=n/a | subsrv=n/a | msg=***********************************************
WARNING: authentication for secure connections is not in use,
It is recommended to enable authentication
*********************************************** | comp=IoTAgent
time=2021-02-03T17:02:30.964Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.Global | from=n/a | srv=n/a | subsrv=n/a | msg=Default expression language not set, or invalid, using legacy configuration | comp=IoTAgent
time=2021-02-03T17:02:30.965Z | lvl=WARN | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.Global | from=n/a | srv=n/a | subsrv=n/a | msg=***********************************************
WARNING: authentication for secure connections is not in use,
It is recommended to enable authentication
*********************************************** | comp=IoTAgent
time=2021-02-03T17:02:30.965Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.Global | from=n/a | srv=n/a | subsrv=n/a | msg=Activating IOT Agent NGSI Library. | comp=IoTAgent
time=2021-02-03T17:02:30.965Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.Global | from=n/a | srv=n/a | subsrv=n/a | msg=MongoDB Device registry selected for NGSI Library | comp=IoTAgent
time=2021-02-03T17:02:31.001Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=First connection attempt | comp=IoTAgent
time=2021-02-03T17:02:31.001Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=Attempting to connect to MongoDB instance. Attempt 1 | comp=IoTAgent
(node:3036) DeprecationWarning: current Server Discovery and Monitoring engine is deprecated, and will be removed in a future version. To use the new Server Discover and Monitoring engine, pass option { useUnifiedTopology: true } to the MongoClient constructor.
time=2021-02-03T17:02:31.021Z | lvl=ERROR | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=MONGODB-001: Error trying to connect to MongoDB: MongoNetworkError: failed to connect to server [localhost:27017] on first connect [Error: connect ECONNREFUSED 127.0.0.1:27017
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1138:16)
    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:131:14) {
  name: 'MongoNetworkError',
  errorLabels: [Array],
  [Symbol(mongoErrorContextSymbol)]: {}
}]
    at Pool.<anonymous> (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/topologies/server.js:431:11)
    at Pool.emit (node:events:376:20)
    at Pool.EventEmitter.emit (node:domain:470:12)
    at /Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/pool.js:580:14
    at /Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:39:11
    at callback (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:261:5)
    at Socket.<anonymous> (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:286:7)
    at Object.onceWrapper (node:events:483:26)
    at Socket.emit (node:events:376:20)
    at Socket.EventEmitter.emit (node:domain:470:12)
    at emitErrorNT (node:internal/streams/destroy:188:8)
    at emitErrorCloseNT (node:internal/streams/destroy:153:3)
    at processTicksAndRejections (node:internal/process/task_queues:80:21) {
  errorLabels: [Array],
  [Symbol(mongoErrorContextSymbol)]: {}
} | comp=IoTAgent
time=2021-02-03T17:02:31.022Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=Waiting 5 seconds before attempting again. | comp=IoTAgent
time=2021-02-03T17:02:36.028Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=Attempting to connect to MongoDB instance. Attempt 2 | comp=IoTAgent
time=2021-02-03T17:02:36.037Z | lvl=ERROR | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=MONGODB-001: Error trying to connect to MongoDB: MongoNetworkError: failed to connect to server [localhost:27017] on first connect [Error: connect ECONNREFUSED 127.0.0.1:27017
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1138:16)
    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:131:14) {
  name: 'MongoNetworkError',
  errorLabels: [Array],
  [Symbol(mongoErrorContextSymbol)]: {}
}]
    at Pool.<anonymous> (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/topologies/server.js:431:11)
    at Pool.emit (node:events:376:20)
    at Pool.EventEmitter.emit (node:domain:470:12)
    at /Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/pool.js:580:14
    at /Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:39:11
    at callback (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:261:5)
    at Socket.<anonymous> (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:286:7)
    at Object.onceWrapper (node:events:483:26)
    at Socket.emit (node:events:376:20)
    at Socket.EventEmitter.emit (node:domain:470:12)
    at emitErrorNT (node:internal/streams/destroy:188:8)
    at emitErrorCloseNT (node:internal/streams/destroy:153:3)
    at processTicksAndRejections (node:internal/process/task_queues:80:21) {
  errorLabels: [Array],
  [Symbol(mongoErrorContextSymbol)]: {}
} | comp=IoTAgent
time=2021-02-03T17:02:36.038Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=Waiting 5 seconds before attempting again. | comp=IoTAgent
time=2021-02-03T17:02:41.043Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=Attempting to connect to MongoDB instance. Attempt 3 | comp=IoTAgent
time=2021-02-03T17:02:41.054Z | lvl=ERROR | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=MONGODB-001: Error trying to connect to MongoDB: MongoNetworkError: failed to connect to server [localhost:27017] on first connect [Error: connect ECONNREFUSED 127.0.0.1:27017
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1138:16)
    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:131:14) {
  name: 'MongoNetworkError',
  errorLabels: [Array],
  [Symbol(mongoErrorContextSymbol)]: {}
}]
    at Pool.<anonymous> (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/topologies/server.js:431:11)
    at Pool.emit (node:events:376:20)
    at Pool.EventEmitter.emit (node:domain:470:12)
    at /Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/pool.js:580:14
    at /Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:39:11
    at callback (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:261:5)
    at Socket.<anonymous> (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:286:7)
    at Object.onceWrapper (node:events:483:26)
    at Socket.emit (node:events:376:20)
    at Socket.EventEmitter.emit (node:domain:470:12)
    at emitErrorNT (node:internal/streams/destroy:188:8)
    at emitErrorCloseNT (node:internal/streams/destroy:153:3)
    at processTicksAndRejections (node:internal/process/task_queues:80:21) {
  errorLabels: [Array],
  [Symbol(mongoErrorContextSymbol)]: {}
} | comp=IoTAgent
time=2021-02-03T17:02:41.055Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=Waiting 5 seconds before attempting again. | comp=IoTAgent
time=2021-02-03T17:02:46.060Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=Attempting to connect to MongoDB instance. Attempt 4 | comp=IoTAgent
time=2021-02-03T17:02:46.068Z | lvl=ERROR | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=MONGODB-001: Error trying to connect to MongoDB: MongoNetworkError: failed to connect to server [localhost:27017] on first connect [Error: connect ECONNREFUSED 127.0.0.1:27017
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1138:16)
    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:131:14) {
  name: 'MongoNetworkError',
  errorLabels: [Array],
  [Symbol(mongoErrorContextSymbol)]: {}
}]
    at Pool.<anonymous> (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/topologies/server.js:431:11)
    at Pool.emit (node:events:376:20)
    at Pool.EventEmitter.emit (node:domain:470:12)
    at /Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/pool.js:580:14
    at /Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:39:11
    at callback (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:261:5)
    at Socket.<anonymous> (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:286:7)
    at Object.onceWrapper (node:events:483:26)
    at Socket.emit (node:events:376:20)
    at Socket.EventEmitter.emit (node:domain:470:12)
    at emitErrorNT (node:internal/streams/destroy:188:8)
    at emitErrorCloseNT (node:internal/streams/destroy:153:3)
    at processTicksAndRejections (node:internal/process/task_queues:80:21) {
  errorLabels: [Array],
  [Symbol(mongoErrorContextSymbol)]: {}
} | comp=IoTAgent
time=2021-02-03T17:02:46.069Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=Waiting 5 seconds before attempting again. | comp=IoTAgent
time=2021-02-03T17:02:51.074Z | lvl=INFO | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=Attempting to connect to MongoDB instance. Attempt 5 | comp=IoTAgent
time=2021-02-03T17:02:51.081Z | lvl=ERROR | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=MONGODB-001: Error trying to connect to MongoDB: MongoNetworkError: failed to connect to server [localhost:27017] on first connect [Error: connect ECONNREFUSED 127.0.0.1:27017
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1138:16)
    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:131:14) {
  name: 'MongoNetworkError',
  errorLabels: [Array],
  [Symbol(mongoErrorContextSymbol)]: {}
}]
    at Pool.<anonymous> (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/topologies/server.js:431:11)
    at Pool.emit (node:events:376:20)
    at Pool.EventEmitter.emit (node:domain:470:12)
    at /Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/pool.js:580:14
    at /Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:39:11
    at callback (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:261:5)
    at Socket.<anonymous> (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:286:7)
    at Object.onceWrapper (node:events:483:26)
    at Socket.emit (node:events:376:20)
    at Socket.EventEmitter.emit (node:domain:470:12)
    at emitErrorNT (node:internal/streams/destroy:188:8)
    at emitErrorCloseNT (node:internal/streams/destroy:153:3)
    at processTicksAndRejections (node:internal/process/task_queues:80:21) {
  errorLabels: [Array],
  [Symbol(mongoErrorContextSymbol)]: {}
} | comp=IoTAgent
time=2021-02-03T17:02:51.082Z | lvl=ERROR | corr=6639dee1-9575-4efe-8deb-f7de9b73c876 | trans=6639dee1-9575-4efe-8deb-f7de9b73c876 | op=IoTAgentNGSI.DbConn | from=n/a | srv=n/a | subsrv=n/a | msg=MONGODB-002: Error found after [5] attempts: MongoNetworkError: failed to connect to server [localhost:27017] on first connect [Error: connect ECONNREFUSED 127.0.0.1:27017
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1138:16)
    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:131:14) {
  name: 'MongoNetworkError',
  errorLabels: [Array],
  [Symbol(mongoErrorContextSymbol)]: {}
}]
    at Pool.<anonymous> (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/topologies/server.js:431:11)
    at Pool.emit (node:events:376:20)
    at Pool.EventEmitter.emit (node:domain:470:12)
    at /Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/pool.js:580:14
    at /Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:39:11
    at callback (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:261:5)
    at Socket.<anonymous> (/Users/dalxds/Developer/uni/sigfox-iotagent/node_modules/mongoose/node_modules/mongodb/lib/core/connection/connect.js:286:7)
    at Object.onceWrapper (node:events:483:26)
    at Socket.emit (node:events:376:20)
    at Socket.EventEmitter.emit (node:domain:470:12)
    at emitErrorNT (node:internal/streams/destroy:188:8)
    at emitErrorCloseNT (node:internal/streams/destroy:153:3)
    at processTicksAndRejections (node:internal/process/task_queues:80:21) {
  errorLabels: [Array],
  [Symbol(mongoErrorContextSymbol)]: {}
} | comp=IoTAgent```

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

The issue names no source file or test. Start by reproducing agent startup with MongoDB and trace the connection path associated with IoTAgentNGSI.DbConn, comparing the first attempt with later retries. Done means the agent connects successfully on its first attempt without waiting for a retry.

Written by the indexing model from the issue text.

Assessment

Tech stack
javascript, mongodb
Domain
backend, databases
Issue type
Bug
Difficulty
3/5
Estimated time
1-2 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
28/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.