Azure / Azure/azure-service-bus-java
MessageSender is unable to recover from network outage
- Dominant language
- Java
- Stars
- 62
- Forks
- 63
- PR merge metrics
- No merged PRs in 30d
Description
I use an IMessageSender created by `ClientFactory.createMessageSenderFromConnectionStringBuilder` to feed a queue that I created according to the [samples repository](https://github.com/Azure/azure-service-bus/tree/master/samples/Java). It works well until I simulate a network outage. First, I simulated the network outage by turning off the WiFi on my laptop. I got send timeout errors for a while and when I turned the WiFi back, it kept giving timeout exceptions. I thought that turning off the WiFi is too destructive, it can cause problems in the networking stack so I went more subtle. Currently I simulate the network outage by dropping incoming packets for 45 seconds.
```
sudo iptables -I INPUT -i wlan0 -j DROP ; sleep 45; sudo iptables -D INPUT -i wlan0 -j DROP;
```
Networking is restored after 45 seconds, but I keep getting the timeouts seemingly indefinitely.
```
2018-11-24 19:04:20.794 TRACE 24344 --- [pool-1-thread-1] c.n.asrscenariomanager.RunQueueFeeder : Sending message to run queue for run 1dce6166-311b-421c-aa74-4c22371983ea
2018-11-24 19:04:50.796 WARN 24344 --- [pool-4-thread-1] c.m.a.s.primitives.CoreMessageSender : Delivery '22f5e3aa46124c0890d3fa02098caad6' to 'BasicQueue' did not receive ack from service. Throwing timeout.
2018-11-24 19:04:50.800 ERROR 24344 --- [pool-4-thread-1] c.m.a.s.primitives.CoreMessageSender : Send timed out
com.microsoft.azure.servicebus.primitives.TimeoutException: Send operation timed out at 2018-11-24T19:04:50.797Z[Europe/London].
at com.microsoft.azure.servicebus.primitives.CoreMessageSender.throwSenderTimeout(CoreMessageSender.java:887) [azure-servicebus-1.2.8.jar:na]
at com.microsoft.azure.servicebus.primitives.CoreMessageSender.access$500(CoreMessageSender.java:59) [azure-servicebus-1.2.8.jar:na]
at com.microsoft.azure.servicebus.primitives.CoreMessageSender$3.run(CoreMessageSender.java:260) [azure-servicebus-1.2.8.jar:na]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_91]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
2018-11-24 19:04:50.803 ERROR 24344 --- [pool-3-thread-3] c.n.asrscenariomanager.RunQueueFeeder : Failed to process run queue for run 1dce6166-311b-421c-aa74-4c22371983ea: java.util.concurrent.CompletionException: com.microsoft.azure.servicebus.primitives.TimeoutException: Send operation timed out at 2018-11-24T19:04:50.797Z[Europe/London]., errorContext[NS: nmisbtest.servicebus.windows.net, PATH: BasicQueue, REFERENCE_ID: 42e9c9_880ac5bed8fd483f86aa5944d05aed9b_G28, LINK_CREDIT: 998]
2018-11-24 19:04:50.997 TRACE 24344 --- [pool-1-thread-1] c.n.asrscenariomanager.RunQueueFeeder : Sending message to run queue for run 1dce6166-311b-421c-aa74-4c22371983ea
2018-11-24 19:05:20.997 WARN 24344 --- [pool-4-thread-3] c.m.a.s.primitives.CoreMessageSender : Delivery '6d9af9eb32cb4addb9205fc8d2df292e' to 'BasicQueue' did not receive ack from service. Throwing timeout.
2018-11-24 19:05:20.998 ERROR 24344 --- [pool-4-thread-3] c.m.a.s.primitives.CoreMessageSender : Send timed out
com.microsoft.azure.servicebus.primitives.TimeoutException: Send operation timed out at 2018-11-24T19:05:20.998Z[Europe/London].
at com.microsoft.azure.servicebus.primitives.CoreMessageSender.throwSenderTimeout(CoreMessageSender.java:887) [azure-servicebus-1.2.8.jar:na]
at com.microsoft.azure.servicebus.primitives.CoreMessageSender.access$500(CoreMessageSender.java:59) [azure-servicebus-1.2.8.jar:na]
at com.microsoft.azure.servicebus.primitives.CoreMessageSender$3.run(CoreMessageSender.java:260) [azure-servicebus-1.2.8.jar:na]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_91]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
2018-11-24 19:05:20.999 ERROR 24344 --- [pool-3-thread-3] c.n.asrscenariomanager.RunQueueFeeder : Failed to process run queue for run 1dce6166-311b-421c-aa74-4c22371983ea: java.util.concurrent.CompletionException: com.microsoft.azure.servicebus.primitives.TimeoutException: Send operation timed out at 2018-11-24T19:05:20.998Z[Europe/London]., errorContext[NS: nmisbtest.servicebus.windows.net, PATH: BasicQueue, REFERENCE_ID: 42e9c9_880ac5bed8fd483f86aa5944d05aed9b_G28, LINK_CREDIT: 997]
2018-11-24 19:05:21.160 TRACE 24344 --- [pool-1-thread-1] c.n.asrscenariomanager.RunQueueFeeder : Sending message to run queue for run 1dce6166-311b-421c-aa74-4c22371983ea
2018-11-24 19:05:51.161 WARN 24344 --- [pool-4-thread-4] c.m.a.s.primitives.CoreMessageSender : Delivery '1cee2726058d4a1d9b6966d87edc879e' to 'BasicQueue' did not receive ack from service. Throwing timeout.
2018-11-24 19:05:51.161 ERROR 24344 --- [pool-4-thread-4] c.m.a.s.primitives.CoreMessageSender : Send timed out
com.microsoft.azure.servicebus.primitives.TimeoutException: Send operation timed out at 2018-11-24T19:05:51.161Z[Europe/London].
at com.microsoft.azure.servicebus.primitives.CoreMessageSender.throwSenderTimeout(CoreMessageSender.java:887) [azure-servicebus-1.2.8.jar:na]
at com.microsoft.azure.servicebus.primitives.CoreMessageSender.access$500(CoreMessageSender.java:59) [azure-servicebus-1.2.8.jar:na]
at com.microsoft.azure.servicebus.primitives.CoreMessageSender$3.run(CoreMessageSender.java:260) [azure-servicebus-1.2.8.jar:na]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_91]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
2018-11-24 19:05:51.162 ERROR 24344 --- [pool-3-thread-3] c.n.asrscenariomanager.RunQueueFeeder : Failed to process run queue for run 1dce6166-311b-421c-aa74-4c22371983ea: java.util.concurrent.CompletionException: com.microsoft.azure.servicebus.primitives.TimeoutException: Send operation timed out at 2018-11-24T19:05:51.161Z[Europe/London]., errorContext[NS: nmisbtest.servicebus.windows.net, PATH: BasicQueue, REFERENCE_ID: 42e9c9_880ac5bed8fd483f86aa5944d05aed9b_G28, LINK_CREDIT: 996]
2018-11-24 19:05:51.297 TRACE 24344 --- [pool-1-thread-1] c.n.asrscenariomanager.RunQueueFeeder : Sending message to run queue for run 1dce6166-311b-421c-aa74-4c22371983ea
2018-11-24 19:06:21.298 WARN 24344 --- [pool-4-thread-2] c.m.a.s.primitives.CoreMessageSender : Delivery '8dff44d9d8b540b581df5a9309ffa1bd' to 'BasicQueue' did not receive ack from service. Throwing timeout.
2018-11-24 19:06:21.299 ERROR 24344 --- [pool-4-thread-2] c.m.a.s.primitives.CoreMessageSender : Send timed out
com.microsoft.azure.servicebus.primitives.TimeoutException: Send operation timed out at 2018-11-24T19:06:21.299Z[Europe/London].
at com.microsoft.azure.servicebus.primitives.CoreMessageSender.throwSenderTimeout(CoreMessageSender.java:887) [azure-servicebus-1.2.8.jar:na]
at com.microsoft.azure.servicebus.primitives.CoreMessageSender.access$500(CoreMessageSender.java:59) [azure-servicebus-1.2.8.jar:na]
at com.microsoft.azure.servicebus.primitives.CoreMessageSender$3.run(CoreMessageSender.java:260) [azure-servicebus-1.2.8.jar:na]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_91]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_91]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_91]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_91]
2018-11-24 19:06:21.300 ERROR 24344 --- [pool-3-thread-3] c.n.asrscenariomanager.RunQueueFeeder : Failed to process run queue for run 1dce6166-311b-421c-aa74-4c22371983ea: java.util.concurrent.CompletionException: com.microsoft.azure.servicebus.primitives.TimeoutException: Send operation timed out at 2018-11-24T19:06:21.299Z[Europe/London]., errorContext[NS: nmisbtest.servicebus.windows.net, PATH: BasicQueue, REFERENCE_ID: 42e9c9_880ac5bed8fd483f86aa5944d05aed9b_G28, LINK_CREDIT: 995]
```
If I restart the application the message is sent right away.
**Environment:**
- OS: Ubuntu 18.04
- SDK Version 1.2.8
- Oracle JAVA 1.8.0_91
Contributor guide
Assessment
This issue has not been assessed yet.