Elevated Rate of DEADLINE_EXCEEDED

[PeterLavetsky]

For quite some time we've been making SearchStream calls with a GrpcCallContext timeout duration of 5 minutes and this has served us well.

In the last two days, over a wide range of customers and queries, we've seen a much higher rate of calls timing out with DEADLINE_EXCEEDED:

./new-google-requests-detail.2021-02-22.log : 0
./new-google-requests-detail.2021-02-23.log : 4
./new-google-requests-detail.2021-02-24.log : 2
./new-google-requests-detail.2021-02-25.log : 0
./new-google-requests-detail.2021-02-26.log : 1
./new-google-requests-detail.2021-02-27.log : 0
./new-google-requests-detail.2021-02-28.log : 28
./new-google-requests-detail.2021-03-01.log : 3
./new-google-requests-detail.2021-03-02.log : 0
./new-google-requests-detail.2021-03-03.log : 1892
./new-google-requests-detail.2021-03-04.log : 1001

We've been on com.google.api-ads:google-ads:11.0.0 for the duration of the above instance counts.

Request logs deleted

The scope does not seem to be limited to any customer or query.

No RequestIDs available as they're not returned when the Deadline Exceeded is thrown. Is it possible to make those available in a future version?

Thanks
Pete

[nwbirnie]

Hey, I checked the logs on our side and I don't see any of these requests... a couple explanations would be:

• Triggering our ddos protection. Are you possibly creating may service client instances? Each of these will create a new TCP connection and these are quite tightly throttled on our side.
• Change in your binary dependencies. Possibly there was a change to one of the transitive dependencies of the library? For instance, gRPC might have been pushed to an incorrect version. Could you run mvn dependency:list and post the versions used by your project please?

[PeterLavetsky]

Nick,

We cache our service clients

https://github.com/googleads/google-ads-java/issues/301

I just dumped the keys and we have about 22 cached BackgroundResources to service all our client calls

On 3/3 we made 1.2MM SearchStream calls via the cached clients. I don't have the per client call count handy.

./new-google-requests-detail.2021-03-01.log : 3
./new-google-requests-detail.2021-03-02.log : 0
./new-google-requests-detail.2021-03-03.log : 1892
./new-google-requests-detail.2021-03-04.log : 1001

Seems unlikely to go from 0 -> 1892 on the day boundary from a DDOS perspective ...

[nwbirnie]

It's odd, I don't see any record of those queries in our logs for the last 10 days. I even checked it based on a partial match of the GAQL query string and nothing came up. It's likely that it's my query that's wrong, but just to check quickly, would you expect any of those queries to have executed successfully in the recent past?

[PeterLavetsky]

Yes, we're certain that those queries execute successfully.

I'd also be able to show instances where the exact same query for the exact same customer completed successfully earlier in the day as well as later in the day after the DEADLINE_EXCEPTION.

[PeterLavetsky]

Nick,

Here's a post from the API forum with other people reporting they started running into this in the last couple days:

https://groups.google.com/g/adwords-api/c/7uhwVPPZGdA

I think Google added additional DDOS detection at some network level around 3am EST on March 3rd.

Pete

[PeterLavetsky]

Another post with developers stating increased latency over the last few days:

https://groups.google.com/g/adwords-api/c/xfqTous0uA8

[nwbirnie]

Hey, thanks for sharing - it looks like this is a general issue with the API. I'll reach out to some folks to see what we can do.

[PeterLavetsky]

The issue has remained relatively constant from March 3rd to now. It started ( for us ) at 3:09 AM EST on the 3rd of March

new-google-requests-summary.2021-03-03.log 1636
new-google-requests-summary.2021-03-04.log 2571
new-google-requests-summary.2021-03-05.log 2509
new-google-requests-summary.2021-03-06.log 2199
new-google-requests-summary.2021-03-07.log 2205
new-google-requests-summary.2021-03-08.log 1567

traceroute to googleads.googleapis.com (172.217.9.42), 50 hops max, 60 byte packets
 1  ip-172-31-67-206.us-east-2.compute.internal (172.31.67.206)  0.105 ms  0.092 ms  0.079 ms
 2  ec2-52-15-0-35.us-east-2.compute.amazonaws.com (52.15.0.35)  1.219 ms ec2-52-15-0-39.us-east-2.compute.amazonaws.com (52.15.0.39)  6.606 ms  6.569 ms
 3  100.65.27.32 (100.65.27.32)  6.878 ms 100.65.25.176 (100.65.25.176)  6.841 ms 100.65.28.16 (100.65.28.16)  6.387 ms
 4  100.66.13.226 (100.66.13.226)  11.091 ms 100.66.13.242 (100.66.13.242)  2.187 ms 100.66.12.52 (100.66.12.52)  6.016 ms
 5  100.66.14.238 (100.66.14.238)  12.673 ms 100.66.15.66 (100.66.15.66)  19.554 ms 100.66.15.198 (100.66.15.198)  21.682 ms
 6  100.66.6.45 (100.66.6.45)  29.160 ms 100.66.7.207 (100.66.7.207)  18.131 ms 100.66.7.165 (100.66.7.165)  18.005 ms
 7  100.66.5.89 (100.66.5.89)  22.210 ms 100.66.4.47 (100.66.4.47)  14.451 ms 100.66.4.127 (100.66.4.127)  15.892 ms
 8  100.65.15.65 (100.65.15.65)  0.726 ms 100.65.11.33 (100.65.11.33)  0.831 ms 100.65.13.193 (100.65.13.193)  0.696 ms
 9  52.95.1.1 (52.95.1.1)  1.437 ms 52.95.3.127 (52.95.3.127)  1.360 ms 15.230.134.4 (15.230.134.4)  1.751 ms
10  15.230.39.186 (15.230.39.186)  4.878 ms 52.95.2.170 (52.95.2.170)  2.575 ms 15.230.39.178 (15.230.39.178)  2.257 ms
11  52.93.239.8 (52.93.239.8)  1.343 ms 52.95.2.209 (52.95.2.209)  2.869 ms 52.95.2.123 (52.95.2.123)  1.871 ms
12  100.92.53.100 (100.92.53.100)  12.836 ms 100.92.53.56 (100.92.53.56)  12.116 ms 100.92.53.132 (100.92.53.132)  12.026 ms
13  100.92.48.104 (100.92.48.104)  12.372 ms 100.92.43.122 (100.92.43.122)  11.891 ms 100.92.48.122 (100.92.48.122)  12.256 ms
14  100.92.48.133 (100.92.48.133)  12.325 ms 100.92.48.71 (100.92.48.71)  13.264 ms 100.92.43.37 (100.92.43.37)  16.529 ms
15  100.92.49.140 (100.92.49.140)  12.648 ms 100.92.44.60 (100.92.44.60)  11.915 ms 100.92.49.46 (100.92.49.46)  12.517 ms
16  100.92.49.73 (100.92.49.73)  11.739 ms 100.92.49.103 (100.92.49.103)  12.709 ms  12.584 ms
17  52.93.133.110 (52.93.133.110)  12.290 ms 52.93.132.66 (52.93.132.66)  11.940 ms 54.239.43.60 (54.239.43.60)  13.020 ms
18  100.91.163.8 (100.91.163.8)  12.419 ms 100.91.168.76 (100.91.168.76)  12.314 ms 100.91.163.32 (100.91.163.32)  12.396 ms
19  100.91.163.63 (100.91.163.63)  17.122 ms 100.91.163.37 (100.91.163.37)  11.940 ms 100.91.163.87 (100.91.163.87)  12.108 ms
20  100.91.159.142 (100.91.159.142)  12.463 ms 100.91.165.36 (100.91.165.36)  12.304 ms 100.91.160.14 (100.91.160.14)  12.732 ms
21  100.91.159.49 (100.91.159.49)  12.071 ms 100.91.160.49 (100.91.160.49)  12.781 ms 100.91.159.7 (100.91.159.7)  12.839 ms
22  100.91.176.173 (100.91.176.173)  11.731 ms 100.91.176.181 (100.91.176.181)  11.809 ms 100.91.177.71 (100.91.177.71)  11.654 ms
23  100.100.6.35 (100.100.6.35)  12.169 ms 100.100.6.121 (100.100.6.121)  11.979 ms 100.100.8.63 (100.100.8.63)  12.048 ms
24  100.100.69.200 (100.100.69.200)  12.061 ms 100.100.70.6 (100.100.70.6)  12.076 ms 100.100.76.134 (100.100.76.134)  12.114 ms
25  100.100.82.3 (100.100.82.3)  110.249 ms 100.100.76.131 (100.100.76.131)  12.126 ms 100.100.66.3 (100.100.66.3)  12.160 ms
26  100.100.2.46 (100.100.2.46)  12.339 ms 100.100.2.32 (100.100.2.32)  11.871 ms 100.100.34.32 (100.100.34.32)  12.464 ms
27  99.83.68.209 (99.83.68.209)  12.378 ms  12.304 ms  12.186 ms
28  100.100.34.32 (100.100.34.32)  11.997 ms * *
29  108.170.240.97 (108.170.240.97)  12.926 ms 108.170.246.33 (108.170.246.33)  13.050 ms 108.170.240.97 (108.170.240.97)  13.093 ms
30  * 108.170.246.66 (108.170.246.66)  12.396 ms *
31  * * *
32  * * *
33  * * *
34  * * *
35  * * *
36  * * *
37  * * *
38  * * *
39  * * *
40  * * *
41  * * *
42  * * *
43  * * *
44  * * *
45  * * *
46  * * *
47  * * *
48  * * *
49  * * *
50  * * *

[nwbirnie]

Hey, it looks like this issue should now be resolved. Could you confirm?

[PeterLavetsky]

Nick,

I can confirm that the issue is now resolved. We have not seen a DEADLINE_EXCEEDED in over 11 hours.

Thanks
Pete

[nwbirnie]

Thanks again for flagging this.

[PeterLavetsky]

@nwbirnie

We've started seeing a lot of DEADLINE_EXCEEDED again starting around 3:30 AM EST today

new-google-requests-summary.2021-04-18.log 0
new-google-requests-summary.2021-04-19.log 1
new-google-requests-summary.2021-04-20.log 1
new-google-requests-summary.2021-04-21.log 0
new-google-requests-summary.2021-04-22.log 824

traceroute -m 50 googleads.googleapis.com
traceroute to googleads.googleapis.com (172.217.4.42), 50 hops max, 60 byte packets
 1  ip-172-31-130-116.us-east-2.compute.internal (172.31.130.116)  0.072 ms  0.065 ms  0.054 ms
 2  ec2-52-15-0-187.us-east-2.compute.amazonaws.com (52.15.0.187)  5.603 ms ec2-52-15-0-177.us-east-2.compute.amazonaws.com (52.15.0.177)  6.258 ms ec2-52-15-0-171.us-east-2.compute.amazonaws.com (52.15.0.171)  15.464 ms
 3  100.65.26.32 (100.65.26.32)  119.478 ms 100.65.24.128 (100.65.24.128)  5.774 ms 100.65.24.16 (100.65.24.16)  6.584 ms
 4  100.66.13.242 (100.66.13.242)  5.889 ms 100.66.13.82 (100.66.13.82)  5.854 ms 100.66.13.134 (100.66.13.134)  4.246 ms
 5  100.66.15.10 (100.66.15.10)  13.296 ms 100.66.14.232 (100.66.14.232)  14.679 ms 100.66.14.206 (100.66.14.206)  18.132 ms
 6  100.66.6.35 (100.66.6.35)  13.649 ms 100.66.7.205 (100.66.7.205)  18.924 ms 100.66.6.171 (100.66.6.171)  11.839 ms
 7  100.66.5.187 (100.66.5.187)  20.166 ms 100.66.4.169 (100.66.4.169)  22.420 ms 100.66.5.255 (100.66.5.255)  12.245 ms
 8  100.65.15.33 (100.65.15.33)  0.647 ms 100.65.13.97 (100.65.13.97)  4.707 ms 100.65.11.129 (100.65.11.129)  3.479 ms
 9  15.230.135.87 (15.230.135.87)  3.692 ms 15.230.39.121 (15.230.39.121)  2.038 ms 15.230.135.77 (15.230.135.77)  1.005 ms
10  52.95.2.118 (52.95.2.118)  1.110 ms 15.230.140.23 (15.230.140.23)  2.216 ms 15.230.39.134 (15.230.39.134)  1.892 ms
11  52.95.2.177 (52.95.2.177)  0.946 ms 52.95.1.93 (52.95.1.93)  1.223 ms 52.93.239.62 (52.93.239.62)  0.904 ms
12  100.92.53.138 (100.92.53.138)  11.100 ms 100.92.53.118 (100.92.53.118)  11.523 ms 100.92.53.160 (100.92.53.160)  11.248 ms
13  100.92.48.76 (100.92.48.76)  12.095 ms 100.92.43.78 (100.92.43.78)  11.296 ms 100.92.48.26 (100.92.48.26)  12.054 ms
14  100.92.48.45 (100.92.48.45)  11.657 ms 100.92.48.89 (100.92.48.89)  11.223 ms 100.92.48.135 (100.92.48.135)  15.591 ms
15  100.92.44.112 (100.92.44.112)  18.088 ms 100.92.44.110 (100.92.44.110)  17.912 ms 100.92.49.60 (100.92.49.60)  11.877 ms
16  100.92.49.125 (100.92.49.125)  11.903 ms 100.92.44.75 (100.92.44.75)  11.693 ms 100.92.44.129 (100.92.44.129)  12.021 ms
17  54.239.41.111 (54.239.41.111)  11.948 ms 52.93.134.30 (52.93.134.30)  11.352 ms 52.93.132.68 (52.93.132.68)  12.469 ms
18  100.91.163.56 (100.91.163.56)  12.194 ms 100.91.163.124 (100.91.163.124)  11.824 ms 100.91.163.0 (100.91.163.0)  11.732 ms
19  100.91.163.95 (100.91.163.95)  11.436 ms 100.91.163.63 (100.91.163.63)  11.037 ms 100.91.163.93 (100.91.163.93)  11.654 ms
20  100.91.160.134 (100.91.160.134)  12.219 ms 100.91.164.94 (100.91.164.94)  12.033 ms 100.91.159.64 (100.91.159.64)  14.493 ms
21  100.91.160.25 (100.91.160.25)  11.361 ms 100.91.165.105 (100.91.165.105)  12.079 ms 100.91.159.51 (100.91.159.51)  11.764 ms
22  100.91.177.27 (100.91.177.27)  10.850 ms 100.91.176.197 (100.91.176.197)  11.234 ms 100.91.176.159 (100.91.176.159)  11.010 ms
23  100.100.8.99 (100.100.8.99)  11.548 ms 100.100.6.23 (100.100.6.23)  11.505 ms 100.100.8.93 (100.100.8.93)  16.086 ms
24  100.100.72.136 (100.100.72.136)  32.140 ms 100.100.74.8 (100.100.74.8)  11.650 ms 100.100.69.136 (100.100.69.136)  11.353 ms
25  100.100.92.131 (100.100.92.131)  11.270 ms 100.100.93.157 (100.100.93.157)  11.521 ms 100.100.89.35 (100.100.89.35)  11.521 ms
26  100.100.34.40 (100.100.34.40)  14.014 ms 100.100.28.118 (100.100.28.118)  11.158 ms 100.100.2.38 (100.100.2.38)  11.545 ms
27  99.82.181.25 (99.82.181.25)  16.347 ms 100.95.7.17 (100.95.7.17)  11.197 ms 99.83.68.209 (99.83.68.209)  12.198 ms
28  * * *
29  108.170.246.33 (108.170.246.33)  14.180 ms 108.170.240.97 (108.170.240.97)  12.174 ms 108.170.235.158 (108.170.235.158)  11.225 ms
30  108.170.246.67 (108.170.246.67)  11.478 ms 108.170.240.98 (108.170.240.98)  12.080 ms  11.830 ms
31  * * *
32  * * *
33  * * *
34  * * *
35  * * *
36  * * *
37  * * *
38  * * *
39  * * *
40  * * *
41  * * *
42  * * *
43  * * *
44  * * *
45  * * *
46  * * *
47  * * *
48  * * *
49  * * *
50  * * *

It's possible it cleared up just now about ~2 hours later ... but thought I'd flag as a precautionary mesure

Thanks
Pete

[nwbirnie]

Thanks for flagging.

I can see that errors and latency spiked around 3.30am, but it does appear to have been resolved as of around 5.15 am EST.

Please let me know if you continue seeing issues.