search

kmille / smtp_exporter

Prometheus exporter - monitoring for your mail server
12 stars 6 forks source link

invalid memory address or nil pointer dereference if Authentication failed #1

Closed steinbrueckri closed 1 year ago

steinbrueckri commented 1 year ago

I know this repository is under heavy development, but I found something. :)

ts=2023-02-06T15:46:10.539Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Beginning probe" probe=smtp timeout_seconds=120
ts=2023-02-06T15:46:10.540Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Resolving target addresses" targetHost=smtp.mailgun.org ip_protocol=ip4
ts=2023-02-06T15:46:10.540Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Resolved target address" ip=34.83.33.178
ts=2023-02-06T15:46:11.410Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Successfully connected to SMTP server" server=34.83.33.178:587 tls=starttls
ts=2023-02-06T15:46:11.559Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="unsupported value type" err="Authentication failed" code=535 enhancedCode=0
ts=2023-02-06T15:46:11.559Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Checking valid status codes" validStatusCodes=[200]
2023/02/06 16:46:11 http: panic serving 127.0.0.1:40044: runtime error: invalid memory address or nil pointer dereference
goroutine 70 [running]:
net/http.(*conn).serve.func1()
        /usr/lib/go/src/net/http/server.go:1850 +0xbf
panic({0x956700, 0xe23da0})
        /usr/lib/go/src/runtime/panic.go:890 +0x262
github.com/kmille/smtp_exporter/prober.SMTPProber.func1(0xc0004f0000?, {0xabf800?, 0xc000180040?}, {0xc0000bb590, 0x1, 0x1})
        /home/steinbrueckri/smtp_exporter/prober/smtp.go:89 +0xab
github.com/kmille/smtp_exporter/prober.SMTPProber.func2()
        /home/steinbrueckri/smtp_exporter/prober/smtp.go:131 +0x10d
github.com/kmille/smtp_exporter/prober.SMTPProber({_, _}, {_, _}, {{0xc000028c48, 0x4}, 0x0, {{0xc000028c58, 0x3}, 0x1, ...}, ...}, ...)
        /home/steinbrueckri/smtp_exporter/prober/smtp.go:157 +0x127e
main.probeHandler({0xac38e0, 0xc000234380}, 0xc000144300, 0xc000014098, {0xabfbc0, 0xc0000252f0}, 0x0?)
        /home/steinbrueckri/smtp_exporter/main.go:115 +0xa0f
main.run.func5({0xac38e0, 0xc000234380}, 0x4ccdb3?)
        /home/steinbrueckri/smtp_exporter/main.go:326 +0xdd
net/http.HandlerFunc.ServeHTTP(0xc0000eaaf0?, {0xac38e0?, 0xc000234380?}, 0x0?)
        /usr/lib/go/src/net/http/server.go:2109 +0x2f
net/http.(*ServeMux).ServeHTTP(0xc00029c84b?, {0xac38e0, 0xc000234380}, 0xc000144300)
        /usr/lib/go/src/net/http/server.go:2487 +0x149
net/http.serverHandler.ServeHTTP({0xc000229380?}, {0xac38e0, 0xc000234380}, 0xc000144300)
        /usr/lib/go/src/net/http/server.go:2947 +0x30c
net/http.(*conn).serve(0xc0002208c0, {0xac4148, 0xc0000b6960})
        /usr/lib/go/src/net/http/server.go:1991 +0x607
created by net/http.(*Server).Serve
        /usr/lib/go/src/net/http/server.go:3102 +0x4db

Br Richard

kmille commented 1 year ago

Hey this repo is more fallen asleep. Can you give me your config/command line parameters?

steinbrueckri commented 1 year ago

Hi @kmille, thx for the fast response.

Log

$ ./smtp_exporter --web.listen-address="127.0.0.1:9125" --log.level=debug
level=info ts=2023-02-06T17:06:30.639Z caller=main.go:229 msg="Starting smtp_exporter" version="(version=, branch=, revision=)"
level=info ts=2023-02-06T17:06:30.639Z caller=main.go:230 build_context="(go=go1.19.5, user=, date=)"
level=info ts=2023-02-06T17:06:30.640Z caller=main.go:242 msg="Loaded config file"
level=debug ts=2023-02-06T17:06:30.640Z caller=main.go:249 externalURL=http://xxx:9125
level=debug ts=2023-02-06T17:06:30.640Z caller=main.go:263 routePrefix=/
level=info ts=2023-02-06T17:06:30.641Z caller=main.go:401 msg="Listen on address" address=127.0.0.1:9125
level=info ts=2023-02-06T17:06:30.641Z caller=tls_config.go:191 msg="TLS is disabled." http2=false
ts=2023-02-06T17:06:33.951Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Beginning probe" probe=smtp timeout_seconds=120
ts=2023-02-06T17:06:33.951Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Resolving target addresses" targetHost=smtp.mailgun.org ip_protocol=ip4
ts=2023-02-06T17:06:33.953Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Resolved target address" ip=34.150.216.144
ts=2023-02-06T17:06:34.549Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Successfully connected to SMTP server" server=34.150.216.144:587 tls=starttls
ts=2023-02-06T17:06:34.649Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="unsupported value type" err="Authentication failed" code=535 enhancedCode=0
ts=2023-02-06T17:06:34.649Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Checking valid status codes" validStatusCodes=[200]
2023/02/06 18:06:34 http: panic serving 127.0.0.1:35648: runtime error: invalid memory address or nil pointer dereference
goroutine 11 [running]:
net/http.(*conn).serve.func1()
        /usr/lib/go/src/net/http/server.go:1850 +0xbf
panic({0x956700, 0xe23da0})
        /usr/lib/go/src/runtime/panic.go:890 +0x262
github.com/kmille/smtp_exporter/prober.SMTPProber.func1(0xc000388000?, {0xabf800?, 0xc0000a8040?}, {0xc0004a47a0, 0x1, 0x1})
        /home/steinbrueckri/smtp_exporter/prober/smtp.go:89 +0xab
github.com/kmille/smtp_exporter/prober.SMTPProber.func2()
        /home/steinbrueckri/smtp_exporter/prober/smtp.go:131 +0x10d
github.com/kmille/smtp_exporter/prober.SMTPProber({_, _}, {_, _}, {{0xc000028c48, 0x4}, 0x0, {{0xc000028c58, 0x3}, 0x1, ...}, ...}, ...)
        /home/steinbrueckri/smtp_exporter/prober/smtp.go:157 +0x127e
main.probeHandler({0xac38e0, 0xc0001d41c0}, 0xc0001c2300, 0xc0000140a0, {0xabfbc0, 0xc0000252f0}, 0x0?)
        /home/steinbrueckri/smtp_exporter/main.go:115 +0xa0f
main.run.func5({0xac38e0, 0xc0001d41c0}, 0x4ccdb3?)
        /home/steinbrueckri/smtp_exporter/main.go:326 +0xdd
net/http.HandlerFunc.ServeHTTP(0xc0000cbaf0?, {0xac38e0?, 0xc0001d41c0?}, 0x0?)
        /usr/lib/go/src/net/http/server.go:2109 +0x2f
net/http.(*ServeMux).ServeHTTP(0xc00002a30b?, {0xac38e0, 0xc0001d41c0}, 0xc0001c2300)
        /usr/lib/go/src/net/http/server.go:2487 +0x149
net/http.serverHandler.ServeHTTP({0xc000025dd0?}, {0xac38e0, 0xc0001d41c0}, 0xc0001c2300)
        /usr/lib/go/src/net/http/server.go:2947 +0x30c
net/http.(*conn).serve(0xc0001d3400, {0xac4148, 0xc000025ce0})
        /usr/lib/go/src/net/http/server.go:1991 +0x607
created by net/http.(*Server).Serve
        /usr/lib/go/src/net/http/server.go:3102 +0x4db
ts=2023-02-06T17:06:43.879Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="Beginning probe" probe=smtp timeout_seconds=120
ts=2023-02-06T17:06:43.880Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="Resolving target addresses" targetHost=smtp.eu.mailgun.org ip_protocol=ip4
ts=2023-02-06T17:06:43.881Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="Resolved target address" ip=35.240.62.197
ts=2023-02-06T17:06:43.969Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="Successfully connected to SMTP server" server=35.240.62.197:587 tls=starttls
ts=2023-02-06T17:06:44.132Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="SMTP authentication was successful"
ts=2023-02-06T17:06:44.145Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="MAIL FROM command sent successfully" from=xxx
ts=2023-02-06T17:06:44.160Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="RCPT TO command sent successfully" rcpt=xxx
ts=2023-02-06T17:06:44.267Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="Message successfully sent" subject="[smtp_exporter] b5332ed1-70c2-4a71-bbd8-7dd2215d9ea8"
ts=2023-02-06T17:06:44.281Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="Probe succeeded" duration_seconds=0.401510813

First call

curl "http://localhost:9125/probe?target=smtp.mailgun.org:587&module=mailgun"
curl: (52) Empty reply from server

NOTE: The only difference between the two calls is the target, the account is only configured on smtp.eu.mailgun.org not on smtp.mailgun.org

Second call

$ curl "http://localhost:9125/probe?target=smtp.eu.mailgun.org:587&module=mailgun"
# HELP probe_dns_lookup_time_seconds Returns the time taken for probe dns lookup in seconds
# TYPE probe_dns_lookup_time_seconds gauge
probe_dns_lookup_time_seconds 0.001794229
# HELP probe_duration_seconds Returns how long the probe took to complete in seconds
# TYPE probe_duration_seconds gauge
probe_duration_seconds 0.401510813
# HELP probe_ip_addr_hash Specifies the hash of IP address. It's useful to detect if the IP address changes.
# TYPE probe_ip_addr_hash gauge
probe_ip_addr_hash 2.136626741e+09
# HELP probe_ip_protocol Specifies wether probe ip protocol IP4 or IP6
# TYPE probe_ip_protocol gauge
probe_ip_protocol 4
# HELP probe_message_sent Indicates if the message was sent successfully
# TYPE probe_message_sent gauge
probe_message_sent 1
# HELP probe_smtp_enhanced_status_code Response smtp enhanced status code
# TYPE probe_smtp_enhanced_status_code gauge
probe_smtp_enhanced_status_code 200
# HELP probe_smtp_status_code Response smtp status code
# TYPE probe_smtp_status_code gauge
probe_smtp_status_code 221
# HELP probe_smtp_tls Indicates if TLS was used
# TYPE probe_smtp_tls gauge
probe_smtp_tls 1
# HELP probe_success Displays whether or not the probe was a success
# TYPE probe_success gauge
probe_success 1
# HELP probe_tls_cert_expire Returns the TLS cert expire in unixtime
# TYPE probe_tls_cert_expire gauge
probe_tls_cert_expire 1.687996799e+09
# HELP probe_tls_info Contains certificate information
# TYPE probe_tls_info gauge
probe_tls_info{fingerprint_sha256="ee888d854afffa9a0d70e61750c74bd794d13ac264c5cafd76f8ae0fd3d2378f"} 1
# HELP probe_tls_version_info Contains the TLS version used
# TYPE probe_tls_version_info gauge
probe_tls_version_info{version="TLS 1.3"} 1

Config

modules:
  mailgun:
    prober: smtp
    smtp:
      preferred_ip_protocol: ip4
      tls: starttls
      auth:
           username: xxx
           password: xxx
      headers:
        from: xxx
        to: xxx
      valid_status_codes:
      - 200
  ses:
    prober: smtp
    smtp:
      preferred_ip_protocol: ip4
      tls: starttls
      auth:
           username: xxx 
           password: xxx
      headers:
        from: xxx
        to: xxx 
      valid_status_codes:
      - 200
kmille commented 1 year ago

I added a quickfix in cd5207c.

This can happen if we try to send a Quit command, but the connection is already closed by the remote endpoint. Needs better error handling, we can not just use handleSMTPError

In this case: if authentication fails, the server closes the tcp connection. But smtp_exporter tried to send a smtp QUIT command. The error handling es meh and needs to be improved at this point.

Can you please recheck after a git pull?

steinbrueckri commented 1 year ago

Works like a charm ...

level=info ts=2023-02-07T11:05:11.173Z caller=main.go:229 msg="Starting smtp_exporter" version="(version=, branch=, revision=)"
level=info ts=2023-02-07T11:05:11.173Z caller=main.go:230 build_context="(go=go1.19.5, user=, date=)"
level=info ts=2023-02-07T11:05:11.173Z caller=main.go:242 msg="Loaded config file"
level=debug ts=2023-02-07T11:05:11.174Z caller=main.go:249 externalURL=http://xxx:9125
level=debug ts=2023-02-07T11:05:11.174Z caller=main.go:263 routePrefix=/
level=info ts=2023-02-07T11:05:11.174Z caller=main.go:401 msg="Listen on address" address=127.0.0.1:9125
level=info ts=2023-02-07T11:05:11.175Z caller=tls_config.go:191 msg="TLS is disabled." http2=false
ts=2023-02-07T11:05:19.108Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="Beginning probe" probe=smtp timeout_seconds=120
ts=2023-02-07T11:05:19.109Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="Resolving target addresses" targetHost=smtp.eu.mailgun.org ip_protocol=ip4
ts=2023-02-07T11:05:19.111Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="Resolved target address" ip=35.240.62.197
ts=2023-02-07T11:05:19.264Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="Successfully connected to SMTP server" server=35.240.62.197:587 tls=starttls
ts=2023-02-07T11:05:19.281Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="SMTP authentication was successful"
ts=2023-02-07T11:05:19.295Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="MAIL FROM command sent successfully" from=xxx
ts=2023-02-07T11:05:19.309Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="RCPT TO command sent successfully" rcpt=xxx
ts=2023-02-07T11:05:19.379Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="Message successfully sent" subject="[smtp_exporter] 6dbb8034-3090-4b6f-8e59-1bd3747c13b1"
ts=2023-02-07T11:05:19.393Z caller=main.go:172 module=mailgun target=smtp.eu.mailgun.org:587 level=debug msg="Probe succeeded" duration_seconds=0.28451242
ts=2023-02-07T11:05:23.204Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Beginning probe" probe=smtp timeout_seconds=120
ts=2023-02-07T11:05:23.204Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Resolving target addresses" targetHost=smtp.mailgun.org ip_protocol=ip4
ts=2023-02-07T11:05:23.205Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Resolved target address" ip=34.83.33.178
ts=2023-02-07T11:05:24.069Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Successfully connected to SMTP server" server=34.83.33.178:587 tls=starttls
ts=2023-02-07T11:05:24.217Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="unsupported value type" err="Authentication failed" code=535 enhancedCode=0
ts=2023-02-07T11:05:24.218Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Checking valid status codes" validStatusCodes=[200]
ts=2023-02-07T11:05:24.218Z caller=main.go:172 module=mailgun target=smtp.mailgun.org:587 level=debug msg="Probe failed" duration_seconds=1.013299081