External MOnitor for LTM using CURL
Hi , i am setting UP an external Monitor using CURL for application monitoring for select number of backend servers . This is the script i am using as per F5 DOC https://support.f5.com/csp/article/K31435017 I am seeing below error while running my Monitor check with backend server : [0][13575] 2021-03-05 19:09:50.903983: ID 221 :(_add_service_list): [ addr=::ffff:10.149.22.25:5550 srcaddr=none mon=/Common/SOLACE_5550 up_intvl=5 dn_intvl=5 timeout=16 time_until_up=0 immed=0 next_ping=[1614942199.877925][2021-03-05 19:03:19] last_ping=[0.000000][1970-01-01 08:00:00] deadline=[1614942220.877925][2021-03-05 19:03:40] on_service_list=True ] [0][13575] 2021-03-05 19:09:50.904855: ID 221 :(monitor_and_params): /Common/SOLACE_5550: ARGS_I= , URI= /health-check/guaranteed-active, RECV= 200 OK, RUN_I= /Common/Curl_Monitor_EX, [ addr=::ffff:10.149.22.25:5550 srcaddr=none mon=/Common/SOLACE_5550 ] [0][13575] 2021-03-05 19:09:50.904908: ID 221 :Probing monitor instance '/Common/SOLACE_5550' '/Common/monitor_test' 5550 [ addr=::ffff:10.149.22.25:5550 srcaddr=none ] [0][13575] 2021-03-05 19:09:50.905000: ID 221 :(main_loop [next_ping]) Closing logging file /var/log/monitors/Common_SOLACE_5550-Common_monitor_test-5550.log [0][13575] 2021-03-05 19:09:50.905084: ID 221 :(_do_ping): time to ping, now=[1614942204.880927][2021-03-05 19:03:24], status=UNKNOWN [ addr=::ffff:10.149.22.25:5550 mon=/Common/SOLACE_5550 fd=-1 pend=0 #conn=0 up_intvl=5 dn_intvl=5 timeout=16 time_until_up=0 immed=0 next_ping=[1614942199.877925][2021-03-05 19:03:19] last_ping=[0.000000][1970-01-01 08:00:00] deadline=[1614942220.877925][2021-03-05 19:03:40] on_service_list=True snd_cnt=0 rcv_cnt=0 ] [0][13575] 2021-03-05 19:09:50.905145: ID 221 :(_spawn_external_pinger): /config/filestore/files_d/Common_d/external_monitor_d/:Common:Curl_Monitor_EX_61726_1 [ addr=::ffff:10.149.22.25:5550 ] [0][13575] 2021-03-05 19:09:50.905819: ID 221 :(_spawn_external_pinger): spawned EAV pid=9276 [ addr=::ffff:10.149.22.25:5550 fd=20 ] [0][13575] 2021-03-05 19:09:50.905924: ID 221 :(_do_ping): post ping, status=UNKNOWN [ addr=::ffff:10.149.22.25:5550 mon=/Common/SOLACE_5550 fd=20 pend=0 #conn=0 up_intvl=5 dn_intvl=5 timeout=16 time_until_up=0 immed=0 next_ping=[1614942209.877925][2021-03-05 19:03:29] last_ping=[1614942204.880927][2021-03-05 19:03:24] deadline=[1614942220.877925][2021-03-05 19:03:40] on_service_list=True snd_cnt=1 rcv_cnt=0 ] [0][13575] 2021-03-05 19:09:50.954396: ID 221 :(_main_loop): Service ready for read, now=[1614942204.929748][2021-03-05 19:03:24] [ addr=::ffff:10.149.22.25:5550 srcaddr=::%0:0 fd=20 pend=0 #conn=0 ] [0][13575] 2021-03-05 19:09:50.954422: ID 221 :(_recv_external_node_ping): reading [ addr=::ffff:10.149.22.25:5550 ] [0][13575] 2021-03-05 19:09:50.954434: ID 221 :(recv_external_node_ping): EAV failed [ addr=::ffff:10.149.22.25:5550 ] I am not sure what is broken . i can ping the server and telnet to the server . i can CURL backend SRV successfully curl -vk http://10.149.22.25:5550/health-check/guaranteed-active * Trying 10.149.22.25... * Connected to 10.149.22.25 (10.149.22.25) port 5550 (#0) > GET /health-check/guaranteed-active HTTP/1.1 > Host: 10.149.22.25:5550 > User-Agent: curl/7.47.1 > Accept: */* > < HTTP/1.1 200 OK < Server: Solace_PubSub+_Enterprise/9.5.0.25 < Cache-Control: no-cache < Content-Length: 0 < * Connection #0 to host 10.149.22.25 left intactNo 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