MqttIOTest testReadNoClientId failure timeout flaky test (sickbayed)
- Dominant language
- Java
- Stars
- 8.7k
- Forks
- 4.7k
- Avg merge
- 2d 2h
- Merged PRs (30d)
- 205
Description
I've seen failures a bit today. Here is one:
[https://builds.apache.org/job/beam_PreCommit_Java_GradleBuild/1758/testReport/junit/org.apache.beam.sdk.io.mqtt/MqttIOTest/testReadNoClientId/](https://builds.apache.org/job/beam_PreCommit_Java_GradleBuild/1758/testReport/junit/org.apache.beam.sdk.io.mqtt/MqttIOTest/testReadNoClientId/)
Filing all flakes as "Critical" priority so we can sickbay or fix.
Since that build will get GC'd, here is the Standard Error. It looks like from that perspective everything went as planned, but perhaps the test has a race condition or something?
```
Feb 01, 2018 11:28:01 PM org.apache.beam.sdk.io.mqtt.MqttIOTest startBroker
INFO: Finding free network
port
Feb 01, 2018 11:28:01 PM org.apache.beam.sdk.io.mqtt.MqttIOTest startBroker
INFO: Starting ActiveMQ
brokerService on 57986
Feb 01, 2018 11:28:03 PM org.apache.activemq.broker.BrokerService doStartPersistenceAdapter
INFO:
Using Persistence Adapter: MemoryPersistenceAdapter
Feb 01, 2018 11:28:04 PM org.apache.activemq.broker.BrokerService
doStartBroker
INFO: Apache ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:1)
is starting
Feb 01, 2018 11:28:04 PM org.apache.activemq.transport.TransportServerThreadSupport doStart
INFO:
Listening for connections at: mqtt://localhost:57986
Feb 01, 2018 11:28:04 PM org.apache.activemq.broker.TransportConnector
start
INFO: Connector mqtt://localhost:57986 started
Feb 01, 2018 11:28:04 PM org.apache.activemq.broker.BrokerService
doStartBroker
INFO: Apache ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:1)
started
Feb 01, 2018 11:28:04 PM org.apache.activemq.broker.BrokerService doStartBroker
INFO: For
help or more information please see: http://activemq.apache.org
Feb 01, 2018 11:28:26 PM org.apache.activemq.broker.BrokerService
stop
INFO: Apache ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:1)
is shutting down
Feb 01, 2018 11:28:26 PM org.apache.activemq.broker.TransportConnector stop
INFO:
Connector mqtt://localhost:57986 stopped
Feb 01, 2018 11:28:26 PM org.apache.activemq.broker.BrokerService
stop
INFO: Apache ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:1)
uptime 24.039 seconds
Feb 01, 2018 11:28:26 PM org.apache.activemq.broker.BrokerService stop
INFO:
Apache ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:1)
is shutdown
Feb 01, 2018 11:28:26 PM org.apache.beam.sdk.io.mqtt.MqttIOTest startBroker
INFO: Finding
free network port
Feb 01, 2018 11:28:26 PM org.apache.beam.sdk.io.mqtt.MqttIOTest startBroker
INFO:
Starting ActiveMQ brokerService on 46799
Feb 01, 2018 11:28:26 PM org.apache.activemq.broker.BrokerService
doStartPersistenceAdapter
INFO: Using Persistence Adapter: MemoryPersistenceAdapter
Feb 01, 2018 11:28:26
PM org.apache.activemq.broker.BrokerService doStartBroker
INFO: Apache ActiveMQ 5.13.1 (localhost,
ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:2) is starting
Feb 01, 2018 11:28:26
PM org.apache.activemq.transport.TransportServerThreadSupport doStart
INFO: Listening for connections
at: mqtt://localhost:46799
Feb 01, 2018 11:28:26 PM org.apache.activemq.broker.TransportConnector start
INFO:
Connector mqtt://localhost:46799 started
Feb 01, 2018 11:28:26 PM org.apache.activemq.broker.BrokerService
doStartBroker
INFO: Apache ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:2)
started
Feb 01, 2018 11:28:26 PM org.apache.activemq.broker.BrokerService doStartBroker
INFO: For
help or more information please see: http://activemq.apache.org
Feb 01, 2018 11:28:28 PM org.apache.beam.sdk.io.mqtt.MqttIOTest
lambda$testRead$1
INFO: Waiting pipeline connected to the MQTT broker before sending messages ...
Feb
01, 2018 11:28:35 PM org.apache.activemq.broker.BrokerService stop
INFO: Apache ActiveMQ 5.13.1 (localhost,
ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:2) is shutting down
Feb 01, 2018 11:28:35
PM org.apache.activemq.broker.TransportConnector stop
INFO: Connector mqtt://localhost:46799 stopped
Feb
01, 2018 11:28:35 PM org.apache.activemq.broker.BrokerService stop
INFO: Apache ActiveMQ 5.13.1 (localhost,
ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:2) uptime 9.430 seconds
Feb 01, 2018
11:28:35 PM org.apache.activemq.broker.BrokerService stop
INFO: Apache ActiveMQ 5.13.1 (localhost,
ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:2) is shutdown
Feb 01, 2018 11:28:35
PM org.apache.beam.sdk.io.mqtt.MqttIOTest startBroker
INFO: Finding free network port
Feb 01, 2018
11:28:35 PM org.apache.beam.sdk.io.mqtt.MqttIOTest startBroker
INFO: Starting ActiveMQ brokerService
on 54229
Feb 01, 2018 11:28:35 PM org.apache.activemq.broker.BrokerService doStartPersistenceAdapter
INFO:
Using Persistence Adapter: MemoryPersistenceAdapter
Feb 01, 2018 11:28:35 PM org.apache.activemq.broker.BrokerService
doStartBroker
INFO: Apache ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:3)
is starting
Feb 01, 2018 11:28:35 PM org.apache.activemq.transport.TransportServerThreadSupport doStart
INFO:
Listening for connections at: mqtt://localhost:54229
Feb 01, 2018 11:28:35 PM org.apache.activemq.broker.TransportConnector
start
INFO: Connector mqtt://localhost:54229 started
Feb 01, 2018 11:28:35 PM org.apache.activemq.broker.BrokerService
doStartBroker
INFO: Apache ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:3)
started
Feb 01, 2018 11:28:35 PM org.apache.activemq.broker.BrokerService doStartBroker
INFO: For
help or more information please see: http://activemq.apache.org
Feb 01, 2018 11:28:38 PM org.apache.activemq.broker.BrokerService
stop
INFO: Apache ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:3)
is shutting down
Feb 01, 2018 11:28:38 PM org.apache.activemq.broker.TransportConnector stop
INFO:
Connector mqtt://localhost:54229 stopped
Feb 01, 2018 11:28:38 PM org.apache.activemq.broker.BrokerService
stop
INFO: Apache ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:3)
uptime 2.709 seconds
Feb 01, 2018 11:28:38 PM org.apache.activemq.broker.BrokerService stop
INFO:
Apache ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:3)
is shutdown
Feb 01, 2018 11:28:38 PM org.apache.beam.sdk.io.mqtt.MqttIOTest startBroker
INFO: Finding
free network port
Feb 01, 2018 11:28:38 PM org.apache.beam.sdk.io.mqtt.MqttIOTest startBroker
INFO:
Starting ActiveMQ brokerService on 53109
Feb 01, 2018 11:28:38 PM org.apache.activemq.broker.BrokerService
doStartPersistenceAdapter
INFO: Using Persistence Adapter: MemoryPersistenceAdapter
Feb 01, 2018 11:28:38
PM org.apache.activemq.broker.BrokerService doStartBroker
INFO: Apache ActiveMQ 5.13.1 (localhost,
ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:4) is starting
Feb 01, 2018 11:28:38
PM org.apache.activemq.transport.TransportServerThreadSupport doStart
INFO: Listening for connections
at: mqtt://localhost:53109
Feb 01, 2018 11:28:38 PM org.apache.activemq.broker.TransportConnector start
INFO:
Connector mqtt://localhost:53109 started
Feb 01, 2018 11:28:38 PM org.apache.activemq.broker.BrokerService
doStartBroker
INFO: Apache ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:4)
started
Feb 01, 2018 11:28:38 PM org.apache.activemq.broker.BrokerService doStartBroker
INFO: For
help or more information please see: http://activemq.apache.org
Feb 01, 2018 11:28:39 PM org.apache.beam.sdk.io.mqtt.MqttIOTest
lambda$testReadNoClientId$0
INFO: Waiting pipeline connected to the MQTT broker before sending messages
...
Feb 01, 2018 11:29:38 PM org.apache.activemq.broker.BrokerService stop
INFO: Apache ActiveMQ 5.13.1
(localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:4) is shutting down
Feb
01, 2018 11:29:38 PM org.apache.activemq.transport.tcp.TcpTransportServer$2 run
INFO: socketQueue interrupted
- stopping
Feb 01, 2018 11:29:38 PM org.apache.activemq.broker.TransportConnector$1 onAcceptError
SEVERE:
Could not accept connection : java.lang.InterruptedException
Feb 01, 2018 11:29:38 PM org.apache.activemq.broker.TransportConnector
stop
INFO: Connector mqtt://localhost:53109 stopped
Feb 01, 2018 11:29:38 PM org.apache.activemq.broker.BrokerService
stop
INFO: Apache ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:4)
uptime 1 minute
Feb 01, 2018 11:29:38 PM org.apache.activemq.broker.BrokerService stop
INFO: Apache
ActiveMQ 5.13.1 (localhost, ID:115.98.154.104.bc.googleusercontent.com-38646-1517527683931-0:4) is shutdown
```
Imported from Jira [BEAM-3604](https://issues.apache.org/jira/browse/BEAM-3604). Original Jira may contain additional context.
Reported by: kenn.
Contributor guide
Research direction
Start with the MqttIOTest testReadNoClientId failure and its startBroker setup, then run the targeted test to reproduce the timeout. Inspect the pipeline-connection wait shown in the logs and compare it with the test's expected completion. Done means the test reliably completes without timing out under repeated runs.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- java
- Domain
- testing-qa
- Issue type
- Bug
- Difficulty
- 3/5
- Estimated time
- 1-2 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100