No successful responses received before deadline
Hi everyone, we have faced some weird behavior from F5 HTTPS monitor, t the thing is that for every "Time until up" value except " 0 " we get: "No successful responses received before the deadline" the send string from f5 always get to the server and the server always returns the expected value in return as it is shown from the Monitor Debug`s log. but if we set the time until up value for example here, we set timers like this : interval : 1 Up Interval :28 Time Until Up : 30 Timeout : 60 then pool member status will change to down with the:"No successful responses received before the deadline" as a reason. we already have more than 50 pools on the box but it is happening just for this pool members. obviously, it is related to the timers and the way the pool member sends the response, as u can see the mean latency for the monitor is 6663ms . but I couldn`t figure out that where is the exact problem and how I can fix it. [0][13398] 2021-03-01 16:43:49.402857: ID 387:(do_ssl_write): incoming state: 4 [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.402868: ID 387:(do_ssl_write) legacy mode: false [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.407439: ID 387:(do_ssl_write): state: 4 [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.415536: ID 387:(_main_loop): Service ready for read, now=[1614604429.415518][2021-03-01 16:43:49] [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 fd=49 pend=0 #conn=0 ] [0][13398] 2021-03-01 16:43:49.415552: ID 387:(_recv_active_service_ping): reading [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.415559: ID 387:(do_ssl_read) legacy mode: false [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.415577: ID 387:(do_ssl_read): state: 4 [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.415583: ID 387:(_send_active_service_ping): pinging [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.415591: ID 387:(_send_active_service_ping): writing [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] send=GET /status\x0d\x0a\x0d\x0a [0][13398] 2021-03-01 16:43:49.415603: ID 387:(do_ssl_write): incoming state: 4 [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.415615: ID 387:(do_ssl_write) legacy mode: false [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.415680: ID 387:(do_ssl_write): state: 3 [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.415692: ID 387:(_send_active_service_ping): sent ping [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 mon=/Common/BTEST fd=49 pend=0 #conn=0 up_intvl=28 dn_intvl=1 timeout=60 time_until_up=30 immed=0 next_ping=[1614604429.582780][2021-03-01 16:43:49] last_ping=[1614604428.598267][2021-03-01 16:43:48] deadline=[1614604444.616555][2021-03-01 16:44:04] on_service_list=True snd_cnt=15 rcv_cnt=2 ] [0][13398] 2021-03-01 16:43:49.418768: ID 387:(_main_loop): Service ready for read, now=[1614604429.418759][2021-03-01 16:43:49] [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 fd=49 pend=0 #conn=0 ] [0][13398] 2021-03-01 16:43:49.418781: ID 387:(_recv_active_service_ping): reading [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.418787: ID 387:(do_ssl_read) legacy mode: false [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.418793: ID 387:(do_ssl_read): state: 3 [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.418835: ID 387:(addPingEvent): probe latency 6821.46ms; mean latency 6663ms; standard deviation 251.943ms; confidence interval 707.214ms; divergence limit 8328.75ms (mean + 25%); confidence interval limit 7370.22ms; status DOWN. (history buffer contains 11 events (11 timing events) over 72.2718 seconds) [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.418848: ID 387:(_recv_active_service_ping): rcvd 113 bytes: -->{"serviceName":"Bill.Api","version":"3.2.0.0","description":"Bill.Api","serverTime":"2021/03/01 16:43:49 +03:30"}<-- [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 ] [0][13398] 2021-03-01 16:43:49.418855: ID 387:(_ssl_shutdown_service): shutting down, return ssl true [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60264 mon=/Common/BTEST fd=49 ] [0][13398] 2021-03-01 16:43:49.418915: ID 387:(shutdown_service) Closing logging file /var/log/monitors/Common_BTEST-Common_testbill-443.log [0][13398] 2021-03-01 16:43:49.418970: ID 387:(_recv_active_service_ping): got data [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=none ] [0][13398] 2021-03-01 16:43:49.418995: ID 387:(adjust_deadline): from [1614604444.616555][2021-03-01 16:44:04] to [1614604458.598267][2021-03-01 16:44:18] [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 mon=/Common/BTEST fd=-1 pend=0 #conn=0 up_intvl=28 dn_intvl=1 timeout=60 time_until_up=30 immed=0 next_ping=[1614604429.582780][2021-03-01 16:43:49] last_ping=[1614604428.598267][2021-03-01 16:43:48] deadline=[1614604458.598267][2021-03-01 16:44:18] on_service_list=True snd_cnt=1 rcv_cnt=0 ] [0][13398] 2021-03-01 16:43:49.419023: ID 387:(_response_success): going UP [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=none mon=/Common/BTEST up_intvl=28 dn_intvl=1 timeout=60 time_until_up=30 immed=0 next_ping=[1614604429.582780][2021-03-01 16:43:49] last_ping=[1614604428.598267][2021-03-01 16:43:48] deadline=[1614604458.598267][2021-03-01 16:44:18] on_service_list=True snd_cnt=1 rcv_cnt=0 ] [0][13398] 2021-03-01 16:43:49.629712: ID 387:(main_loop [next_ping]) Closing logging file /var/log/monitors/Common_BTEST-Common_testbill-443.log [0][13398] 2021-03-01 16:43:49.629806: ID 387:(_do_ping): time to ping, now=[1614604429.629547][2021-03-01 16:43:49], status=DOWN [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 mon=/Common/BTEST fd=-1 pend=0 #conn=0 up_intvl=28 dn_intvl=1 timeout=60 time_until_up=30 immed=0 next_ping=[1614604429.582780][2021-03-01 16:43:49] last_ping=[1614604428.598267][2021-03-01 16:43:48] deadline=[1614604458.598267][2021-03-01 16:44:18] on_service_list=True snd_cnt=1 rcv_cnt=1 ] [0][13398] 2021-03-01 16:43:49.629837: ID 387:(_send_active_service_ping): pinging [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=none ] [0][13398] 2021-03-01 16:43:49.629844: ID 387:(_connect_to_service): creating new socket (rd0) [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 ] [0][13398] 2021-03-01 16:43:49.629945: ID 387:(_connect_to_service): connect: Operation now in progress [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60884 ] [0][13398] 2021-03-01 16:43:49.629967: ID 387:(_do_ping): post ping, status=DOWN [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 mon=/Common/BTEST fd=23 pend=1 #conn=1 up_intvl=28 dn_intvl=1 timeout=60 time_until_up=30 immed=0 next_ping=[1614604430.582780][2021-03-01 16:43:50] last_ping=[1614604429.629547][2021-03-01 16:43:49] deadline=[1614604458.598267][2021-03-01 16:44:18] on_service_list=True snd_cnt=2 rcv_cnt=1 ] [0][13398] 2021-03-01 16:43:49.630847: ID 387:(_main_loop): Activity on pending service, now=[1614604429.630825][2021-03-01 16:43:49] [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60884 fd=23 pend=1 #conn=1 ] [0][13398] 2021-03-01 16:43:49.630860: ID 387:(_send_active_service_ping): pinging [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60884 ] [0][13398] 2021-03-01 16:43:49.630875: ID 387:(_send_active_service_ping): writing [ tmm?=false td=true tr=false addr=::ffff:192.168.152.243:443 srcaddr=::ffff:192.168.152.241%0:60884 ] send=GET /status\x0d\x0a\x0d\x0a