search

Waziup / WaziGate

Waziup LoRa Edge gateway
21 stars 20 forks source link

LoRa values not received: Chirpstack "context deadline exceeded" #132

Closed cdupont closed 2 years ago

cdupont commented 3 years ago

With the ISO 2.1.2, LoRa messages seems not received.

Chirpstack doesn't seem to be working: image

wazigate-lora logs:

2020-12-11T15:49:46.806146544Z --- Init ChirpStack
2020-12-11T15:49:48.367917012Z Organization "chirpstack" OK.
2020-12-11T15:49:48.368020382Z Network-server id 1 does not exist !?
2020-12-11T15:49:51.873403790Z The ChirpStack data has not changed.
2020-12-11T15:49:51.873712770Z Err grpc: can not create network-server: rpc error: code = Unknown desc = context deadline exceeded

chirpstack-network-server logs:

time="2020-12-11T15:53:27Z" level=info msg="uplink: frame(s) collected" ctx_id=5e1475dc-217d-47e2-99bc-5017ed94abaf mtype=UnconfirmedDataUp uplink_ids="[ed332582-9f3b-49b8-b97c-ccfb5f758ca4]"
time="2020-12-11T15:53:27Z" level=error msg="get gateway error" ctx_id=5e1475dc-217d-47e2-99bc-5017ed94abaf error="get gateway error: object does not exist" gateway_id=0242ac1200023c89
time="2020-12-11T15:53:27Z" level=error msg="uplink: processing uplink frame error" ctx_id=5e1475dc-217d-47e2-99bc-5017ed94abaf error="get device-session error: object does not exist"

chirpstack-application-server logs:

time="2020-12-11T15:55:23Z" level=warning msg="ccResolverWrapper: reporting error to cc: dns: A record lookup error: lookup chirpstack-network-server on 127.0.0.11:53: dial udp 127.0.0.11:53: operation was canceled"
time="2020-12-11T15:55:23Z" level=error msg="finished unary call with code Unknown" ctx_id=586d28cd-8b73-4f16-8ed2-88bdaa0857a2 error="rpc error: code = Unknown desc = context deadline exceeded" grpc.code=Unknown grpc.method=Create grpc.service=api.NetworkServerService grpc.start_time="2020-12-11T15:55:18Z" grpc.time_ms=5007.046 peer.address="172.18.0.10:42492" span.kind=server system=grpc
time="2020-12-11T15:55:27Z" level=info msg="finished unary call with code OK" ctx_id=feb1e2b1-72ce-416c-ad79-02547c2fb934 grpc.code=OK grpc.method=Login grpc.service=api.InternalService grpc.start_time="2020-12-11T15:55:27Z" grpc.time_ms=3.257 peer.address="172.18.0.10:42492" span.kind=server system=grpc
time="2020-12-11T15:55:28Z" level=info msg="finished unary call with code OK" ctx_id=8d54e848-0541-4fb1-b689-9cbb092f6e86 grpc.code=OK grpc.method=Login grpc.service=api.InternalService grpc.start_time="2020-12-11T15:55:28Z" grpc.time_ms=3.067 peer.address="172.18.0.10:42498" span.kind=server system=grpc
time="2020-12-11T15:55:28Z" level=warning msg="Deprecated Authorization header : RFC1945 format expected : Authorization: <type> <credentials>"
time="2020-12-11T15:55:28Z" level=info msg="finished unary call with code OK" ctx_id=b48340b3-2554-4c5f-8b09-7a965dd862aa grpc.code=OK grpc.method=Get grpc.service=api.OrganizationService grpc.start_time="2020-12-11T15:55:28Z" grpc.time_ms=5.38 peer.address="172.18.0.10:42498" span.kind=server system=grpc
time="2020-12-11T15:55:28Z" level=warning msg="Deprecated Authorization header : RFC1945 format expected : Authorization: <type> <credentials>"
time="2020-12-11T15:55:28Z" level=warning msg="Deprecated Authorization header : RFC1945 format expected : Authorization: <type> <credentials>"
cdupont commented 3 years ago

Seems to be due to a DNS problem: https://forum.chirpstack.io/t/error-while-adding-network-server-on-docker/7432/7

My Chirpstack versions: image

cdupont commented 3 years ago

The Chirpstack application server cannot communicate to the network server, probably due to that docker DNS problem. The problem crops up on the UI as well, when I try to do any action: image

One solution could be to fix IP addresses for the docker containers (you can do that in the docker-compose.yml). That would avoid any DNS problem. Maybe the latest version of Chirpstack solved this problem?

mojtaba-esk commented 3 years ago

I do not receive messages on ChirpStack. On forwarder they are received.

On forwarder:

[     ] rx: LoRa: 868.10 MHz, SF12 BW125 CR4/5, Data: QIcdASaAAwAB78qXt5P6UPA=
[     ] received 1 packets, pushing to upstream ...
[     ] (-> 172.18.0.6:1700) PushData: Token: DE69, Gateway ID: AA55A00000000000, 1 rx packets
[     ] (<- 172.18.0.6:1700) PushAck: Token: DE69
[     ] waiting for packets ...

On Bridge:

time="2020-12-15T13:24:08Z" level=info msg="starting ChirpStack Gateway Bridge" docs="https://www.chirpstack.io/gateway-bridge/" version=3.7.1-4-gbb68681
time="2020-12-15T13:24:08Z" level=info msg="backend/semtechudp: starting gateway udp listener" addr="0.0.0.0:1700"
time="2020-12-15T13:24:09Z" level=info msg="integration/mqtt: connected to mqtt broker"
time="2020-12-15T13:24:13Z" level=info msg="integration/mqtt: subscribing to topic" qos=0 topic="gateway/aa55a00000000000/command/#"

On Network-server:

time="2020-12-15T13:26:02Z" level=warning msg="storage: ping PostgreSQL database error, will retry in 2s" error="dial tcp 172.18.0.2:5432: connect: connection refused"
time="2020-12-15T13:26:04Z" level=warning msg="storage: ping PostgreSQL database error, will retry in 2s" error="dial tcp 172.18.0.2:5432: connect: connection refused"
time="2020-12-15T13:26:06Z" level=warning msg="storage: ping PostgreSQL database error, will retry in 2s" error="dial tcp 172.18.0.2:5432: connect: connection refused"
time="2020-12-15T13:26:08Z" level=warning msg="storage: ping PostgreSQL database error, will retry in 2s" error="dial tcp 172.18.0.2:5432: connect: connection refused"
time="2020-12-15T13:26:10Z" level=warning msg="storage: ping PostgreSQL database error, will retry in 2s" error="dial tcp 172.18.0.2:5432: connect: connection refused"
time="2020-12-15T13:26:12Z" level=warning msg="storage: ping PostgreSQL database error, will retry in 2s" error="dial tcp 172.18.0.2:5432: connect: connection refused"
time="2020-12-15T13:26:14Z" level=info msg="storage: applying PostgreSQL data migrations"
time="2020-12-15T13:27:01Z" level=info msg="storage: PostgreSQL data migrations applied" count=25
time="2020-12-15T13:27:01Z" level=info msg="gateway/mqtt: connecting to mqtt broker" server="tcp://wazigate-edge:1883"
time="2020-12-15T13:27:01Z" level=info msg="no geolocation-server configured"
time="2020-12-15T13:27:01Z" level=info msg="configuring join-server client" ca_cert= server="http://chirpstack-application-server:8003" tls_cert= tls_key=
time="2020-12-15T13:27:01Z" level=info msg="backend/gateway: connected to mqtt server"
time="2020-12-15T13:27:01Z" level=info msg="gateway/mqtt: subscribing to gateway event topic" qos=0 topic=gateway/+/event/+
time="2020-12-15T13:27:01Z" level=info msg="service-profile and device-profile redis cache flushed"
time="2020-12-15T13:27:01Z" level=info msg="api: starting network-server api server" bind="0.0.0.0:8000" ca-cert= tls-cert= tls-key=
time="2020-12-15T13:27:01Z" level=info msg="starting downlink device-queue scheduler"
time="2020-12-15T13:27:01Z" level=info msg="starting multicast scheduler"
time="2020-12-15T13:28:09Z" level=info msg="routing-profile created" ctx_id=24823f7e-8b9f-444e-b42c-e04d612c5d5c id=6d5db27e-4ce2-4b2b-b5d7-91f069397978
time="2020-12-15T13:28:09Z" level=info msg="finished unary call with code OK" ctx_id=24823f7e-8b9f-444e-b42c-e04d612c5d5c grpc.code=OK grpc.method=CreateRoutingProfile grpc.service=ns.NetworkServerService grpc.start_time="2020-12-15T13:28:09Z" grpc.time_ms=15.978 peer.address="172.18.0.7:58350" span.kind=server system=grpc
time="2020-12-15T13:28:10Z" level=info msg="service-profile created" ctx_id=e5e73e45-8f0b-4ad1-8ddc-bd3a73b647c0 id=1b011b02-da2d-4473-87ec-a0d68c2f70b6
time="2020-12-15T13:28:10Z" level=info msg="finished unary call with code OK" ctx_id=e5e73e45-8f0b-4ad1-8ddc-bd3a73b647c0 grpc.code=OK grpc.method=CreateServiceProfile grpc.service=ns.NetworkServerService grpc.start_time="2020-12-15T13:28:10Z" grpc.time_ms=14.004 peer.address="172.18.0.7:58350" span.kind=server system=grpc
time="2020-12-15T13:28:10Z" level=info msg="gateway created" ctx_id=92c9006b-443e-4143-9866-078dd4933ab0 gateway_id=aa55a00000000000
time="2020-12-15T13:28:10Z" level=info msg="finished unary call with code OK" ctx_id=92c9006b-443e-4143-9866-078dd4933ab0 grpc.code=OK grpc.method=CreateGateway grpc.service=ns.NetworkServerService grpc.start_time="2020-12-15T13:28:10Z" grpc.time_ms=16.357 peer.address="172.18.0.7:58350" span.kind=server system=grpc
time="2020-12-15T13:28:10Z" level=info msg="device-profile created" ctx_id=7d7e03a0-e6d2-4b50-8f9d-790aacc12ddb id=873cf7f2-9cb8-4caf-b3c3-26646c8815b6
time="2020-12-15T13:28:10Z" level=info msg="finished unary call with code OK" ctx_id=7d7e03a0-e6d2-4b50-8f9d-790aacc12ddb grpc.code=OK grpc.method=CreateDeviceProfile grpc.service=ns.NetworkServerService grpc.start_time="2020-12-15T13:28:10Z" grpc.time_ms=12.618 peer.address="172.18.0.7:58350" span.kind=server system=grpc
time="2020-12-15T14:26:08Z" level=info msg="finished unary call with code OK" ctx_id=fee36206-08c7-4037-9bcf-962ee2464987 grpc.code=OK grpc.method=GetGateway grpc.service=ns.NetworkServerService grpc.start_time="2020-12-15T14:26:08Z" grpc.time_ms=11.683 peer.address="172.18.0.7:58350" span.kind=server system=grpc
time="2020-12-15T14:26:51Z" level=info msg="device created" ctx_id=47c3ce5a-0838-4b90-8657-ea3b126c135c dev_eui=aa555a0026011d87
time="2020-12-15T14:26:51Z" level=info msg="finished unary call with code OK" ctx_id=47c3ce5a-0838-4b90-8657-ea3b126c135c grpc.code=OK grpc.method=CreateDevice grpc.service=ns.NetworkServerService grpc.start_time="2020-12-15T14:26:51Z" grpc.time_ms=22.497 peer.address="172.18.0.7:58350" span.kind=server system=grpc
time="2020-12-15T14:26:51Z" level=info msg="finished unary call with code NotFound" ctx_id=4a360847-51df-4b9d-ba24-3822a5628399 error="rpc error: code = NotFound desc = object does not exist" grpc.code=NotFound grpc.method=GetDeviceActivation grpc.service=ns.NetworkServerService grpc.start_time="2020-12-15T14:26:51Z" grpc.time_ms=4.583 peer.address="172.18.0.7:58350" span.kind=server system=grpc
time="2020-12-15T14:26:51Z" level=info msg="finished unary call with code OK" ctx_id=b9db9c08-d75c-48cb-bbcc-c4b81e3565fc grpc.code=OK grpc.method=GetDeviceProfile grpc.service=ns.NetworkServerService grpc.start_time="2020-12-15T14:26:51Z" grpc.time_ms=7.648 peer.address="172.18.0.7:58350" span.kind=server system=grpc
time="2020-12-15T14:26:51Z" level=info msg="finished unary call with code NotFound" ctx_id=5ff6429e-9f0d-4501-b44b-a6a0243fe11d error="rpc error: code = NotFound desc = object does not exist" grpc.code=NotFound grpc.method=DeactivateDevice grpc.service=ns.NetworkServerService grpc.start_time="2020-12-15T14:26:51Z" grpc.time_ms=1.118 peer.address="172.18.0.7:58350" span.kind=server system=grpc
time="2020-12-15T14:26:51Z" level=info msg="device updated" ctx_id=d2adfd09-e9dd-4d7d-8f24-d4057420e341 dev_eui=aa555a0026011d87
time="2020-12-15T14:26:51Z" level=info msg="device-session saved" ctx_id=d2adfd09-e9dd-4d7d-8f24-d4057420e341 dev_addr=26011d87 dev_eui=aa555a0026011d87
time="2020-12-15T14:26:51Z" level=info msg="device-queue flushed" ctx_id=d2adfd09-e9dd-4d7d-8f24-d4057420e341 dev_eui=aa555a0026011d87
time="2020-12-15T14:26:51Z" level=info msg="finished unary call with code OK" ctx_id=d2adfd09-e9dd-4d7d-8f24-d4057420e341 grpc.code=OK grpc.method=ActivateDevice grpc.service=ns.NetworkServerService grpc.start_time="2020-12-15T14:26:51Z" grpc.time_ms=34.427 peer.address="172.18.0.7:58350" span.kind=server system=grpc

On Application-server:

time="2020-12-15T14:26:08Z" level=info msg="finished unary call with code OK" ctx_id=12b7f186-87ac-4ba8-a5df-f733b2cb0ca6 grpc.code=OK grpc.method=Get grpc.service=api.GatewayService grpc.start_time="2020-12-15T14:26:08Z" grpc.time_ms=33.524 peer.address="127.0.0.1:49978" span.kind=server system=grpc
time="2020-12-15T14:26:08Z" level=info msg="finished unary call with code OK" ctx_id=0b4f99b2-c3cb-46a9-84a3-d71e347bd17b grpc.code=OK grpc.method=GetStats grpc.service=api.GatewayService grpc.start_time="2020-12-15T14:26:08Z" grpc.time_ms=11.509 peer.address="127.0.0.1:49978" span.kind=server system=grpc
time="2020-12-15T14:26:10Z" level=info msg="finished client streaming call" grpc.code=OK grpc.method=StreamFrameLogsForGateway grpc.service=ns.NetworkServerService grpc.time_ms=0.189 span.kind=client system=grpc
time="2020-12-15T14:26:51Z" level=warning msg="Deprecated Authorization header : RFC1945 format expected : Authorization: <type> <credentials>"
time="2020-12-15T14:26:51Z" level=info msg="finished unary call with code NotFound" ctx_id=d33f9c0c-fc7d-4d5b-a429-6769121a6bf6 error="rpc error: code = NotFound desc = object does not exist" grpc.code=NotFound grpc.method=Get grpc.service=api.DeviceService grpc.start_time="2020-12-15T14:26:51Z" grpc.time_ms=20.934 peer.address="172.18.0.10:59176" span.kind=server system=grpc
time="2020-12-15T14:26:51Z" level=warning msg="Deprecated Authorization header : RFC1945 format expected : Authorization: <type> <credentials>"
time="2020-12-15T14:26:51Z" level=info msg="finished client unary call" ctx_id=6ddb5e1e-dc4b-4a6b-aa22-9cdd91793f7f grpc.code=OK grpc.ctx_id=47c3ce5a-0838-4b90-8657-ea3b126c135c grpc.duration=28.13979ms grpc.method=CreateDevice grpc.service=ns.NetworkServerService span.kind=client system=grpc
time="2020-12-15T14:26:51Z" level=info msg="device created" ctx_id=6ddb5e1e-dc4b-4a6b-aa22-9cdd91793f7f dev_eui=aa555a0026011d87
time="2020-12-15T14:26:51Z" level=info msg="finished unary call with code OK" ctx_id=6ddb5e1e-dc4b-4a6b-aa22-9cdd91793f7f grpc.code=OK grpc.method=Create grpc.service=api.DeviceService grpc.start_time="2020-12-15T14:26:51Z" grpc.time_ms=80.607 peer.address="172.18.0.10:59176" span.kind=server system=grpc
time="2020-12-15T14:26:51Z" level=warning msg="Deprecated Authorization header : RFC1945 format expected : Authorization: <type> <credentials>"
time="2020-12-15T14:26:51Z" level=info msg="finished client unary call" ctx_id=99e792ef-ae57-4d4e-9690-f5fcffb6efdf error="rpc error: code = NotFound desc = object does not exist" grpc.code=NotFound grpc.ctx_id=4a360847-51df-4b9d-ba24-3822a5628399 grpc.duration=9.003855ms grpc.method=GetDeviceActivation grpc.service=ns.NetworkServerService span.kind=client system=grpc
time="2020-12-15T14:26:51Z" level=info msg="finished unary call with code NotFound" ctx_id=99e792ef-ae57-4d4e-9690-f5fcffb6efdf error="rpc error: code = NotFound desc = object does not exist" grpc.code=NotFound grpc.method=GetActivation grpc.service=api.DeviceService grpc.start_time="2020-12-15T14:26:51Z" grpc.time_ms=30.353 peer.address="172.18.0.10:59176" span.kind=server system=grpc
time="2020-12-15T14:26:51Z" level=warning msg="Deprecated Authorization header : RFC1945 format expected : Authorization: <type> <credentials>"
time="2020-12-15T14:26:51Z" level=info msg="finished client unary call" ctx_id=4e15a63b-bad0-4761-912d-1ad43ac9e87a grpc.code=OK grpc.ctx_id=b9db9c08-d75c-48cb-bbcc-c4b81e3565fc grpc.duration=12.933261ms grpc.method=GetDeviceProfile grpc.service=ns.NetworkServerService span.kind=client system=grpc
time="2020-12-15T14:26:51Z" level=info msg="finished client unary call" ctx_id=4e15a63b-bad0-4761-912d-1ad43ac9e87a error="rpc error: code = NotFound desc = object does not exist" grpc.code=NotFound grpc.ctx_id=5ff6429e-9f0d-4501-b44b-a6a0243fe11d grpc.duration=5.036847ms grpc.method=DeactivateDevice grpc.service=ns.NetworkServerService span.kind=client system=grpc
time="2020-12-15T14:26:51Z" level=info msg="device activation updated" ctx_id=4e15a63b-bad0-4761-912d-1ad43ac9e87a dev_addr=26011d87 dev_eui=aa555a0026011d87
time="2020-12-15T14:26:51Z" level=info msg="finished client unary call" ctx_id=4e15a63b-bad0-4761-912d-1ad43ac9e87a grpc.code=OK grpc.ctx_id=d2adfd09-e9dd-4d7d-8f24-d4057420e341 grpc.duration=38.597857ms grpc.method=ActivateDevice grpc.service=ns.NetworkServerService span.kind=client system=grpc
time="2020-12-15T14:26:51Z" level=info msg="device activated" ctx_id=4e15a63b-bad0-4761-912d-1ad43ac9e87a dev_addr=26011d87 dev_eui=aa555a0026011d87
time="2020-12-15T14:26:51Z" level=info msg="finished unary call with code OK" ctx_id=4e15a63b-bad0-4761-912d-1ad43ac9e87a grpc.code=OK grpc.method=Activate grpc.service=api.DeviceService grpc.start_time="2020-12-15T14:26:51Z" grpc.time_ms=104.638 peer.address="172.18.0.10:59176" span.kind=server system=grpc
time="2020-12-15T14:28:09Z" level=info msg="finished unary call with code OK" ctx_id=d710bd75-e167-46d1-ba22-53056141d9e4 grpc.code=OK grpc.method=Login grpc.service=api.InternalService grpc.start_time="2020-12-15T14:28:09Z" grpc.time_ms=4.765 peer.address="172.18.0.10:59176" span.kind=server system=grpc
time="2020-12-15T14:33:09Z" level=info msg="finished unary call with code OK" ctx_id=c4674007-83e3-479b-bdce-66193490241a grpc.code=OK grpc.method=Login grpc.service=api.InternalService grpc.start_time="2020-12-15T14:33:09Z" grpc.time_ms=6.138 peer.address="172.18.0.10:59176" span.kind=server system=grpc
time="2020-12-15T14:38:09Z" level=info msg="finished unary call with code OK" ctx_id=7f1d0dcc-5169-4cb0-8157-0d95c922238f grpc.code=OK grpc.method=Login grpc.service=api.InternalService grpc.start_time="2020-12-15T14:38:09Z" grpc.time_ms=4.959 peer.address="172.18.0.10:59176" span.kind=server system=grpc

Postgresql:

PostgreSQL init process complete; ready for start up.

LOG:  database system was shut down at 2020-12-15 13:26:10 UTC
LOG:  MultiXact member wraparound protections are now enabled
LOG:  database system is ready to accept connections
LOG:  autovacuum launcher started
LOG:  using stale statistics instead of current ones because stats collector is not responding

redis:

1:C 15 Dec 2020 13:23:53.275 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
1:C 15 Dec 2020 13:23:53.275 # Redis version=5.0.10, bits=32, commit=00000000, modified=0, pid=1, just started
1:C 15 Dec 2020 13:23:53.275 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
1:M 15 Dec 2020 13:23:53.293 # Warning: 32 bit instance detected but no memory limit set. Setting 3 GB maxmemory limit with 'noeviction' policy now.
1:M 15 Dec 2020 13:23:53.294 * Running mode=standalone, port=6379.
1:M 15 Dec 2020 13:23:53.295 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128.
1:M 15 Dec 2020 13:23:53.295 # Server initialized
1:M 15 Dec 2020 13:23:53.295 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
1:M 15 Dec 2020 13:23:53.296 * Ready to accept connections
1:M 15 Dec 2020 14:26:51.833 * 1 changes in 3600 seconds. Saving...
1:M 15 Dec 2020 14:26:51.834 * Background saving started by pid 12
12:C 15 Dec 2020 14:26:51.886 * DB saved on disk
12:C 15 Dec 2020 14:26:51.887 * RDB: 0 MB of memory used by copy-on-write
1:M 15 Dec 2020 14:26:51.935 * Background saving terminated with success

wazigate-lora:

GET 200 device/id "OK"
Gateway ID: 0242ac120002c562
Proxy listening on 'proxy.sock'.
--- Init ChirpStack
Organization "chirpstack" OK.
Network-server has been created. ID: 1
Service-profile has been created. ID: 1b011b02-da2d-4473-87ec-a0d68c2f70b6
Gateway has been created. ID: AA55A00000000000
Application has been created. ID: 1
Device-profile has been created. ID: 873cf7f2-9cb8-4caf-b3c3-26646c8815b6
The ChirpStack data changed, see 'chirpstack.json'.
--- Init Device
GET 200 devices?meta=lorawan "OK"
There are 0 LoRaWAN devices.
[@] 404, GET /undefined s:19
Err Device "5fd8c78a3a5d2100069ff811" DevEUI: no value
DevEUI AA555A0026011D87 -> Waziup ID 5fd8c78a3a5d2100069ff811
Creating Chirpstack device ... OK
Activating Chirpstack device ... OK
cdupont commented 3 years ago

This seems to be a different problem, could you create another issue? This issue is with the Chirpstack not working when there is no internet (DNS issue). Could you also provide timestamped traces for the forwarder (docker logs --timestamps)? This makes it easier to match things between e.g. forwarder and bridge.

cdupont commented 3 years ago

I got the "context deadline exceeded" issue with a fresh ISO 2.1.3. Solved it by setting the Wifi Internet, AND after rebooting, it was gone.

cdupont commented 2 years ago

closing as not reproduced