Network Error : tls: DialWithDialer timed out

ezequielfalcon · December 7, 2019, 8:21pm

Hi there!
I have an issue on Raspberry Pi based gateways… on boot up only CSGB throws tls timeout and then it unsubscribes from it’s topic. It stopts receiving messages from the network server… the only way to make it work is to restart CSGB manually with systemctl.

I’ve checked and all my certificates and configurations on the broker side seems right. Other MQTT clients like RAK firmware and desktop clients can connect as expected.
We’re using an EMQX cluster on Kubernetes behind a Voyayer Ingress for TLS termination and load balancing.

Here is the log:

-- Logs begin at Thu 2016-11-03 14:16:42 -03. --
dic 05 10:17:12 localhost systemd[1]: Started ChirpStack Gateway Bridge.
dic 05 10:17:13 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T10:17:13-03:00" level=info msg="starting ChirpStack Gateway Bridge" docs="https://www.chirpstack.io/gateway-bridge/" version=3.4.1
dic 05 10:17:13 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T10:17:13-03:00" level=info msg="backend/semtechudp: starting gateway udp listener" addr="0.0.0.0:1700"
dic 05 11:44:54 localhost chirpstack-gateway-bridge[552]: crypto/rand: blocked for 60 seconds waiting to read random data from the kernel
dic 05 11:46:33 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:46:33-03:00" level=error msg="integration/mqtt: connection error" error="Network Error : tls: DialWithDialer timed out"
dic 05 11:46:37 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:46:37-03:00" level=info msg="integration/mqtt: connected to mqtt broker"
dic 05 11:46:37 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:46:37-03:00" level=info msg="integration/mqtt: subscribing to topic" qos=0 topic="gateway/b827ebfffe01adba/command/#"
dic 05 11:46:37 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:46:37-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=01364cd7-01b5-402f-b447-f54f9d6102f2 topic=gateway/b827ebfffe01adba/event/stats
dic 05 11:46:37 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:46:37-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=c7f0871e-416b-40be-9cae-a42dd5f31615 topic=gateway/b827ebfffe01adba/event/stats
dic 05 11:46:37 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:46:37-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=231c7eb0-715d-4030-9011-572b6548797e topic=gateway/b827ebfffe01adba/event/stats
dic 05 11:46:37 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:46:37-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=6c8f31e9-c6cf-4ccb-96b9-1624281fd31d topic=gateway/b827ebfffe01adba/event/stats
dic 05 11:46:37 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:46:37-03:00" level=info msg="integration/mqtt: subscribing to topic" qos=0 topic="gateway/b827ebfffe01adba/command/#"
dic 05 11:46:37 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:46:37-03:00" level=info msg="integration/mqtt: gateway configuration received" topic=gateway/b827ebfffe01adba/command/config
dic 05 11:46:37 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:46:37-03:00" level=info msg="integration/mqtt: unsubscribe topic" topic="gateway/b827ebfffe01adba/command/#"
dic 05 11:46:47 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:46:47-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=0ab77cd1-3bd9-4038-8c87-3093af23d0ea topic=gateway/b827ebfffe01adba/event/stats
dic 05 11:47:17 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:47:17-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=6558ee21-ec19-4fd9-8504-2c86eba82b6a topic=gateway/b827ebfffe01adba/event/stats
dic 05 11:47:47 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:47:47-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=08cfdef8-e3c8-483d-b552-674d86ec0291 topic=gateway/b827ebfffe01adba/event/stats
dic 05 11:48:17 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:48:17-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=bda5aa21-1cbb-4e50-9a2b-288a2c06cd25 topic=gateway/b827ebfffe01adba/event/stats
dic 05 11:48:47 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:48:47-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=ea3646df-5a17-425c-a65a-52e57c69ae65 topic=gateway/b827ebfffe01adba/event/stats

I’ve tried to use a CA cert from our issuer (Let’sEncrypt) but it’s the same. Target levels on the systemctl service seems ok.

Does anyone had this issue before? This started happening with 3.x.

Thanks!

brocaar · December 9, 2019, 12:16pm

dic 05 10:17:13 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T10:17:13-03:00" level=info msg="backend/semtechudp: starting gateway udp listener" addr="0.0.0.0:1700"
dic 05 11:44:54 localhost chirpstack-gateway-bridge[552]: crypto/rand: blocked for 60 seconds waiting to read random data from the kernel
dic 05 11:46:33 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:46:33-03:00" level=error msg="integration/mqtt: connection error" error="Network Error : tls: DialWithDialer timed out"
dic 05 11:46:37 localhost chirpstack-gateway-bridge[552]: time="2019-12-05T11:46:37-03:00" level=info msg="integration/mqtt: connected to mqtt broker"

Is this a permanent error? To me crypto/rand: blocked for 60 seconds waiting to read random data from the kernel looks like this could cause the tls: DialWithDialer timed out. However, it seems to recover after a while: connected to mqtt broker.

The crypto/rand library provides cryptographic secure randomness, but given the error, it looks like the kernel is unable to provide this random data when the Gateway Bridge starts on boot (maybe due to high CPU load on boot or the time the kernel needs to initialize the random generator).

ezequielfalcon · December 11, 2019, 2:53pm

Thanks @brocaar.
CSGB runs in a Raspberry and it’s using Raspbian distribution… I usually update all the packages and maybe it has something to do with that. All this cases are in Raspberry PI based gateways.

I’ll try to test a older version (older kernel) and see if it works better.

PD: It’s not a permanent error… only on bootup. If I restart the service it won’t print that crypto message

ezequielfalcon · February 4, 2020, 11:38am

Partially solved with 3.7 update:

-- Logs begin at Thu 2016-11-03 14:16:42 -03. --
feb 04 08:32:56 localhost systemd[1]: Started ChirpStack Gateway Bridge.
feb 04 08:32:57 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:32:57-03:00" level=info msg="starting ChirpStack Gateway Bridge" docs="https://www.chirpstack.io/gateway-bridge/"                                            version=3.7.0
feb 04 08:32:57 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:32:57-03:00" level=info msg="backend/semtechudp: starting gateway udp listener" addr="0.0.0.0:1700"
feb 04 08:34:06 localhost chirpstack-gateway-bridge[555]: crypto/rand: blocked for 60 seconds waiting to read random data from the kernel
feb 04 08:34:59 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:34:59-03:00" level=error msg="integration/mqtt: connection error" error="Network Error : tls: DialWithDialer timed out"
feb 04 08:35:03 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:35:03-03:00" level=info msg="integration/mqtt: connected to mqtt broker"
feb 04 08:35:03 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:35:03-03:00" level=info msg="integration/mqtt: subscribing to topic" qos=0 topic="gateway/b827ebfffe01adba/command/#"
feb 04 08:35:03 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:35:03-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=65b94c7b-ff17-4eb1-ae67-7f37c06dc367 topic=gateway/b827ebfffe01adba/event/stats
feb 04 08:35:03 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:35:03-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=d2b2a662-2e63-4b2c-a005-1754c0ceb503 topic=gateway/b827ebfffe01adba/event/stats
feb 04 08:35:03 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:35:03-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=638108ba-2f7c-4a4e-aaa6-93d2f6c12b8b topic=gateway/b827ebfffe01adba/event/stats
feb 04 08:35:03 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:35:03-03:00" level=info msg="integration/mqtt: gateway configuration received" topic=gateway/b827ebfffe01adba/command/config
feb 04 08:35:28 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:35:28-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=fb9cdcae-22dd-42b5-a4a3-54e581880a55 topic=gateway/b827ebfffe01adba/event/stats
feb 04 08:35:28 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:35:28-03:00" level=info msg="integration/mqtt: gateway configuration received" topic=gateway/b827ebfffe01adba/command/config
feb 04 08:35:58 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:35:58-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=de2f54e6-bcb0-487b-a43e-014d6ce538d4 topic=gateway/b827ebfffe01adba/event/stats
feb 04 08:35:58 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:35:58-03:00" level=info msg="integration/mqtt: gateway configuration received" topic=gateway/b827ebfffe01adba/command/config
feb 04 08:36:28 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:36:28-03:00" level=info msg="integration/mqtt: publishing event" event=stats qos=0 stats_id=cc045c79-4089-40df-97b9-d75d97f9d017 topic=gateway/b827ebfffe01adba/event/stats
feb 04 08:36:28 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:36:28-03:00" level=info msg="integration/mqtt: gateway configuration received" topic=gateway/b827ebfffe01adba/command/config
feb 04 08:36:36 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:36:36-03:00" level=info msg="integration/mqtt: publishing event" event=up qos=0 topic=gateway/b827ebfffe01adba/event/up uplink_id=83a4ade4-33ad-4ee7-96e0-25f10d83f964
feb 04 08:36:36 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:36:36-03:00" level=info msg="integration/mqtt: downlink frame received" downlink_id=5e3493b4-2639-49e7-9ba0-a0ce5e632cbf gateway_id=b827ebfffe01adba
feb 04 08:36:41 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:36:41-03:00" level=info msg="integration/mqtt: publishing event" event=up qos=0 topic=gateway/b827ebfffe01adba/event/up uplink_id=e76d672b-01ab-434a-a583-ce73b70b144d
feb 04 08:36:42 localhost chirpstack-gateway-bridge[555]: time="2020-02-04T08:36:42-03:00" level=info msg="integration/mqtt: downlink frame received" downlink_id=2c1fd618-e519-40f4-9853-4e772a78d894 gateway_id=b827ebfffe01adba

It still throws TLS error but it doesn’t unsubscribe from it’s topic and everything works as expected.

Thanks @brocaar