search

thin-edge / thin-edge.io

The open edge framework for lightweight IoT devices
https://thin-edge.io
Apache License 2.0
221 stars 54 forks source link

flaky unit test: tedge_mqtt_bridge::bridge bridge_many_messages #3071

Closed albinsuresh closed 1 month ago

albinsuresh commented 2 months ago

Describe the bug

Flaky test: tedge_mqtt_bridge::bridge bridge_many_messages

Multiple failures on workflow:

  1. https://github.com/thin-edge/thin-edge.io/actions/runs/10477586806/job/29019051110
  2. https://github.com/thin-edge/thin-edge.io/actions/runs/10473279982/job/29004814609

Test trace:

--- STDOUT:              tedge_mqtt_bridge::bridge bridge_many_messages ---

running 1 test
test bridge_many_messages ... FAILED

failures:

failures:
    bridge_many_messages

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 5 filtered out; finished in 10.05s

--- STDERR:              tedge_mqtt_bridge::bridge bridge_many_messages ---
[2024-08-20T19:07:00Z ERROR rumqttd::router::routing] [>] incoming; connection_id=0
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] incoming_connect; client_id="console"
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] Client connection registered connection_id=0
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] [<] outgoing; connection_id=0
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] outgoing_ack; client_id="console"
[2024-08-20T19:07:00Z DEBUG rumqttd::router::routing] Acks sent to device acks_count=1
[2024-08-20T19:07:00Z INFO  rumqttd::server::broker] Listening for remote connections config="38509" listen_addr="127.0.0.1:38509"
[2024-08-20T19:07:00Z INFO  rumqttd::link::console] start; console=ConsoleLink { config: ConsoleSettings { listen: "localhost:38515", filter_handle: None }, connection_id: 0, router_tx: Sender, _link_rx: LinkRx { connection_id: 0, router_tx: Sender, router_rx: Receiver, send_buffer: Mutex { data: [] }, cache: [] } }
thread '[2024-08-20T19:07:00Z INFO  rumqttd::server::broker] accept name="38509" addr=127.0.0.1:44750 count=0 tenant=None
[2024-08-20T19:07:00Z ERROR rumqttd::server::broker] remote_link; tenant_id=None
[2024-08-20T19:07:00Z ERROR rumqttd::router::routing] [>] incoming; connection_id=0
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] incoming_connect; client_id="local-test-client"
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] Client connection registered connection_id=1
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] [<] outgoing; connection_id=1
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] outgoing_ack; client_id="local-test-client"
[2024-08-20T19:07:00Z DEBUG rumqttd::router::routing] Acks sent to device acks_count=1
bridge_many_messages' panicked at crates/extensions/tedge_mqtt_bridge/tests/bridge.rs:504:82:
called `Result::unwrap()` on an `Err` value: Os { code: 111, kind: ConnectionRefused, message: "Connection refused" }
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
[2024-08-20T19:07:00Z ERROR tedge_mqtt_bridge::health] MQTT bridge failed to connect to cloud broker: I/O: Connection reset by peer (os error 104)
[2024-08-20T19:07:00Z ERROR rumqttd::router::routing] [>] incoming; connection_id=1
[2024-08-20T19:07:00Z ERROR rumqttd::router::routing] incoming_payload; client_id="local-test-client"
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] subscribe; topic="te/device/main/#" pkid=1
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] Adding subscription on topic te/device/main/#
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] [<] outgoing; connection_id=1
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] outgoing_ack; client_id="local-test-client"
[2024-08-20T19:07:00Z DEBUG rumqttd::router::routing] Acks sent to device acks_count=1
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] outgoing_publish; client_id="local-test-client"
[2024-08-20T19:07:00Z ERROR tedge_mqtt_bridge::health] MQTT bridge failed to connect to cloud broker: I/O: Connection refused (os error 111)
[2024-08-20T19:07:00Z INFO  rumqttd::server::broker] accept name="38509" addr=127.0.0.1:44762 count=1 tenant=None
[2024-08-20T19:07:00Z ERROR rumqttd::server::broker] remote_link; tenant_id=None
[2024-08-20T19:07:00Z ERROR rumqttd::router::routing] [>] incoming; connection_id=0
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] incoming_connect; client_id="console"
[2024-08-20T19:07:00Z INFO  rumqttd::server::broker] Listening for remote connections config="45481" listen_addr="127.0.0.1:45481"
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] Client connection registered connection_id=0
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] [<] outgoing; connection_id=0
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] outgoing_ack; client_id="console"
[2024-08-20T19:07:00Z DEBUG rumqttd::router::routing] Acks sent to device acks_count=1
[2024-08-20T19:07:00Z ERROR rumqttd::router::routing] [>] incoming; connection_id=0
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] incoming_connect; client_id="tedge-mapper-test"
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] Client connection registered connection_id=2
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] [<] outgoing; connection_id=2
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] outgoing_ack; client_id="tedge-mapper-test"
[2024-08-20T19:07:00Z DEBUG rumqttd::router::routing] Acks sent to device acks_count=1
[2024-08-20T19:07:00Z INFO  tedge_mqtt_bridge::health] MQTT bridge connected to local broker
[2024-08-20T19:07:00Z INFO  tedge_mqtt_bridge] Bridge cloud connection "local" subscribing to [Filter = c8y/s/us, Qos = AtLeastOnce]
[2024-08-20T19:07:00Z ERROR rumqttd::router::routing] [>] incoming; connection_id=2
[2024-08-20T19:07:00Z ERROR rumqttd::router::routing] incoming_payload; client_id="tedge-mapper-test"
[2024-08-20T19:07:00Z ERROR rumqttd::router::routing] publish; topic=b"te/device/main/service/tedge-mapper-test/status/health" pkid=1
[2024-08-20T19:07:00Z DEBUG rumqttd::router::routing] Appended to commitlog: te/device/main/#[0, 1) pkid=1
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] [<] outgoing; connection_id=2
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] outgoing_ack; client_id="tedge-mapper-test"
[2024-08-20T19:07:00Z DEBUG rumqttd::router::routing] Acks sent to device acks_count=1
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] [<] outgoing; connection_id=1
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] outgoing_ack; client_id="local-test-client"
[2024-08-20T19:07:00Z DEBUG rumqttd::router::routing] No acks pending
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] outgoing_publish; client_id="local-test-client"
[2024-08-20T19:07:00Z DEBUG rumqttd::router::routing] Forwarding publishes, cursor = te/device/main/#[0, 1) forward count = 1 inflight_count=1 forward_count=1
[2024-08-20T19:07:00Z ERROR rumqttd::router::routing] [>] incoming; connection_id=2
[2024-08-20T19:07:00Z ERROR rumqttd::router::routing] incoming_payload; client_id="tedge-mapper-test"
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] subscribe; topic="c8y/s/us" pkid=2
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] Adding subscription on topic c8y/s/us
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] [<] outgoing; connection_id=2
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] outgoing_ack; client_id="tedge-mapper-test"
[2024-08-20T19:07:00Z DEBUG rumqttd::router::routing] Acks sent to device acks_count=1
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] outgoing_publish; client_id="tedge-mapper-test"
[2024-08-20T19:07:00Z INFO  rumqttd::link::console] start; console=ConsoleLink { config: ConsoleSettings { listen: "localhost:45487", filter_handle: None }, connection_id: 0, router_tx: Sender, _link_rx: LinkRx { connection_id: 0, router_tx: Sender, router_rx: Receiver, send_buffer: Mutex { data: [] }, cache: [] } }
[2024-08-20T19:07:00Z ERROR rumqttd::router::routing] [>] incoming; connection_id=1
[2024-08-20T19:07:00Z ERROR rumqttd::router::routing] incoming_payload; client_id="local-test-client"
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] puback; pkid=1
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] [<] outgoing; connection_id=1
[2024-08-20T19:07:00Z INFO  rumqttd::router::routing] outgoing_ack; client_id="local-test-client"
[2024-08-20T19:07:00Z DEBUG rumqttd::router::routing] No acks pending
thread 'bridge_many_messages' panicked at crates/extensions/tedge_mqtt_bridge/tests/bridge.rs:88:10:
called `Result::unwrap()` on an `Err` value: expecting health message waiting for status to be "up"

Caused by:
    0: timed-out waiting for received message
    1: deadline has elapsed
[2024-08-20T19:07:10Z INFO  rumqttd::server::broker] disconnected error=Custom { kind: ConnectionAborted, error: "connection closed by peer" }
[2024-08-20T19:07:10Z ERROR rumqttd::router::routing] [>] incoming; connection_id=1
[2024-08-20T19:07:10Z INFO  rumqttd::router::routing] incoming_disconnect; client_id="local-test-client"
[2024-08-20T19:07:10Z INFO  rumqttd::router::routing] Disconnecting connection
[2024-08-20T19:07:10Z INFO  rumqttd::server::broker] disconnected error=Custom { kind: ConnectionAborted, error: "connection closed by peer" }
[2024-08-20T19:07:10Z ERROR rumqttd::router::routing] [>] incoming; connection_id=2
[2024-08-20T19:07:10Z INFO  rumqttd::router::routing] incoming_disconnect; client_id="tedge-mapper-test"
[2024-08-20T19:07:10Z INFO  rumqttd::router::routing] Disconnecting connection
[2024-08-20T19:07:10Z ERROR rumqttd::router::routing] [>] incoming; connection_id=1
[2024-08-20T19:07:10Z ERROR rumqttd::router::routing] [>] incoming; connection_id=2
[2024-08-20T19:07:10Z DEBUG rumqttd::router::routing] Appended to commitlog: te/device/main/#[0, 2) pkid=0

To Reproduce

Run: seq 10 | xargs -I {} cargo nextest run bridge_many_messages

The test failed at least once in 10 attempts. Increase the count if that isn't enough in your env.

gligorisaev commented 2 months ago

I have run flake test finder several times and cannot reproduce the issue anymore