blackbox_exporter icon indicating copy to clipboard operation
blackbox_exporter copied to clipboard

Published 20 hours ago • verified publisher icon prometheus

Can't processe multiline expect strings.

Open d-malko opened this issue 3 years ago • 2 comments

I am using latest prom/blackbox-exporter docker container

blackbox_exporter, version 0.17.0 (branch: HEAD, revision: 1bc768014cf6815f7e9d694e0292e77dd10f3235) build user: root@626fb3899f41 build date: 20200619-11:54:41 go version: go1.14.4

blackbox.yml module config.

modules:
    ftp_connect:
    prober: tcp
    timeout: 5s
    tcp:
      query_response:
      - expect: "220"
      - expect: "Name:"
      - send: "LOGIN"
      - expect: "Password:"
      - send: "PASS"
      - expect: "220"
      - expect: "ftp>"
      - send: "bye"

prometheus.yml scrape config.

scrape_configs:
     - job_name: 'blackbox_ftp_connect'
    metrics_path: /probe
    scrape_interval: 10s
    params:
      module: ['ftp_connect']
    static_configs:
      - targets:
        - 192.168.1.1:21
    relabel_configs:
      - source_labels: [__address__]
        target_label: __param_target
      - source_labels: [__param_target]
        target_label: instance
      - target_label: __address__
        replacement: blackbox_exporter:9115

What logging output did you get from adding &debug=true to the probe URL?

level=info ts=2021-04-02T19:08:13.789Z caller=main.go:212 msg="Starting blackbox_exporter" version="(version=0.17.0, branch=HEAD, revision=1bc768014cf6815f7e9d694e0292e77dd10f3235)"
level=info ts=2021-04-02T19:08:13.789Z caller=main.go:213 msg="Build context" (gogo1.14.4,userroot@626fb3899f41,date20200619-11:54:41)=(MISSING)
level=info ts=2021-04-02T19:08:13.792Z caller=main.go:225 msg="Loaded config file"
level=debug ts=2021-04-02T19:08:13.792Z caller=main.go:233 externalURL=http://:9115
level=debug ts=2021-04-02T19:08:13.792Z caller=main.go:247 routePrefix=/
level=info ts=2021-04-02T19:08:13.793Z caller=main.go:369 msg="Listening on address" address=:9115
ts=2021-04-02T19:08:22.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Beginning probe" probe=tcp timeout_seconds=5
ts=2021-04-02T19:08:22.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Resolving target address" ip_protocol=ip6
ts=2021-04-02T19:08:22.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Resolved target address" ip=192.168.1.1
ts=2021-04-02T19:08:22.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Dialing TCP without TLS"
ts=2021-04-02T19:08:22.013Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Successfully dialed"
ts=2021-04-02T19:08:22.014Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Processing query response entry" entry_number=0
ts=2021-04-02T19:08:22.021Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Read line" line="220 ProFTPD 1.3.4a Server (Welcome to  Data Receiver) [192.168.1.1]"
ts=2021-04-02T19:08:22.021Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Regexp matched" regexp="220 ProFTPD " line="220 ProFTPD 1.3.4a Server (Welcome to  Data Receiver) [192.168.1.1]"
ts=2021-04-02T19:08:22.021Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Processing query response entry" entry_number=1
ts=2021-04-02T19:08:27.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Error reading from connection" err="read tcp4 172.19.0.2:40388->192.168.1.1:21: i/o timeout"
ts=2021-04-02T19:08:27.013Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Probe failed" duration_seconds=5.000395753
ts=2021-04-02T19:08:32.011Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Beginning probe" probe=tcp timeout_seconds=5
ts=2021-04-02T19:08:32.011Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Resolving target address" ip_protocol=ip6
ts=2021-04-02T19:08:32.011Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Resolved target address" ip=192.168.1.1
ts=2021-04-02T19:08:32.011Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Dialing TCP without TLS"
ts=2021-04-02T19:08:32.013Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Successfully dialed"
ts=2021-04-02T19:08:32.013Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Processing query response entry" entry_number=0
ts=2021-04-02T19:08:32.021Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Read line" line="220 ProFTPD 1.3.4a Server (Welcome to  Data Receiver) [192.168.1.1]"
ts=2021-04-02T19:08:32.021Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Regexp matched" regexp="220 ProFTPD " line="220 ProFTPD 1.3.4a Server (Welcome to  Data Receiver) [192.168.1.1]"
ts=2021-04-02T19:08:32.021Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Processing query response entry" entry_number=1
ts=2021-04-02T19:08:37.011Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Error reading from connection" err="read tcp4 172.19.0.2:40396->192.168.1.1:21: i/o timeout"
ts=2021-04-02T19:08:37.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Probe failed" duration_seconds=5.000261172
ts=2021-04-02T19:08:42.011Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Beginning probe" probe=tcp timeout_seconds=5
ts=2021-04-02T19:08:42.011Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Resolving target address" ip_protocol=ip6
ts=2021-04-02T19:08:42.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Resolved target address" ip=192.168.1.1
ts=2021-04-02T19:08:42.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Dialing TCP without TLS"
ts=2021-04-02T19:08:42.013Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Successfully dialed"
ts=2021-04-02T19:08:42.013Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Processing query response entry" entry_number=0
ts=2021-04-02T19:08:42.029Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Read line" line="220 ProFTPD 1.3.4a Server (Welcome to  Data Receiver) [192.168.1.1]"
ts=2021-04-02T19:08:42.029Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Regexp matched" regexp="220 ProFTPD " line="220 ProFTPD 1.3.4a Server (Welcome to  Data Receiver) [192.168.1.1]"
ts=2021-04-02T19:08:42.029Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Processing query response entry" entry_number=

What did you do that produced an error?

I want to monitor FTP server and I see the multiline output. When I am trying to monitor with BlackBox it reads only the first line and didn't proceed with the rest.

As you can see from the logfile, first expect matched successfully, but it can't read next string with Name I also tried to run expect: "Name", but it didn't help.

level=info ts=2021-04-02T19:11:27.761Z caller=main.go:369 msg="Listening on address" address=:9115
ts=2021-04-02T19:11:32.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Beginning probe" probe=tcp timeout_seconds=5
ts=2021-04-02T19:11:32.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Resolving target address" ip_protocol=ip6
ts=2021-04-02T19:11:32.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Resolved target address" ip=192.168.1.1
ts=2021-04-02T19:11:32.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Dialing TCP without TLS"
ts=2021-04-02T19:11:32.013Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Successfully dialed"
ts=2021-04-02T19:11:32.013Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Processing query response entry" entry_number=0
ts=2021-04-02T19:11:32.019Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Read line" line="220 ProFTPD 1.3.4a Server (Welcome to Data Receiver) [192.168.1.1]"
ts=2021-04-02T19:11:37.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Error reading from connection" err="read tcp4 172.19.0.2:40844->192.168.1.1:21: i/o timeout"
ts=2021-04-02T19:11:37.012Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Probe failed" duration_seconds=5.000264484
ts=2021-04-02T19:11:42.011Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Beginning probe" probe=tcp timeout_seconds=5
ts=2021-04-02T19:11:42.011Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Resolving target address" ip_protocol=ip6
ts=2021-04-02T19:11:42.011Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Resolved target address" ip=192.168.1.1
ts=2021-04-02T19:11:42.011Z caller=main.go:169 module=ftp_connect target=192.168.1.1:21 level=debug msg="Dialing TCP without TLS"

For testing, I wrote expect script

#!/usr/local/bin/expect
spawn ftp 192.168.1.1
expect "Welcome to Data Receiver"
expect "220"
expect "Name"
send "LOGIN\r"
expect "Password:"
send "PASS\r"
expect "ftp>"
send "bye\r"

It works as expected and finished successfully.

Console output:

 ./test_ftp                                                                                                                                                                                                                                                                                                                              SIGINT(2) ↵  10080  20:57:31
spawn ftp 192.168.1.1
Connected to 192.168.1.1.
220 ProFTPD 1.3.4a Server (Welcome to Medispan Data Receiver) [192.168.1.1]
Name (192.168.1.1:root): LOGIN
331 Password required for LOGIN
Password: 
230 User LOGIN logged in
ftp> %

Can you add the possibility to read line by line? Thanks in advance.

PS: If you'll need some additional information -just ask.

d-malko avatar Apr 02 '21 19:04 d-malko

I've run into this as well today while trying to connect to our internal SMTP server. After the initial "EHLO prober" we send, our server responds back with multiple 250-codes. I've attempted to count the 250 codes manually and add that number of "expect" statements; however, that fails as well. Oddly enough it triggers the "Error reading from connection" err="read tcp4 i/o timeout" as well.

In our case response is: 250-SIZE 36700160 250-PIPELINING 250-DSN 250-ENHANCEDSTATUSCODES 250-STARTTLS 250-AUTH NTLM LOGIN 250-8BITMIME 250-BINARYMIME 250 CHUNKING

And we're hoping that just: - expect: "^250 " would match for them until the next "send"

billabongrob avatar Oct 11 '21 17:10 billabongrob

I was just passing by and saw that someone on Reddit suggested the solution:

    - expect: "^220 ([^ ]+) ESMTP (.+)$"
    - send: "EHLO prober\r"

e.g. you should send \r in the end of the line.

clain23 avatar Feb 26 '24 22:02 clain23