rickbassham / tesla

Golang client for the Tesla owner's API.
ISC License
15 stars 3 forks source link

Fix defer location in conn.go #4

Closed iwvelando closed 4 years ago

iwvelando commented 4 years ago

Background

@rickbassham , I've been using your library for a tesla stats poller service. Recently I noticed I've been getting 408 response codes with some frequency, and eventually data stops flowing in. I noticed:

Jun 23 10:29:53 storage tesla-stats-collector[3911891]: {"level":"warn","ts":1592926193.7139213,"caller":"tesla-stats-collector/main.go:207","msg":"failed to query vehicle [redacted]","op":"main","error":"error performing http request: dial tcp: lookup owner-api.teslamotors.com: too many open files"}

Turns out the service was leaving behind these connections after these errors happened.

Testing

Pre-patch

Here's the status of my poller:

isaac@storage:~$ sudo systemctl status tesla-stats-collector
● tesla-stats-collector.service - Poll Tesla vehicles and submit results to InfluxDB
     Loaded: loaded (/etc/systemd/system/tesla-stats-collector.service; enabled; vendor preset: enabled)
     Active: active (running) since Tue 2020-06-23 23:15:43 CDT; 54s ago
   Main PID: 3975729 (tesla-stats-col)
      Tasks: 13 (limit: 38390)
     Memory: 6.8M
     CGroup: /system.slice/tesla-stats-collector.service
             └─3975729 /usr/local/bin/tesla-stats-collector -config /usr/local/etc/tesla-stats-collector/config.json

Jun 23 23:15:43 storage systemd[1]: Started Poll Tesla vehicles and submit results to InfluxDB.
Jun 23 23:16:26 storage tesla-stats-collector[3975729]: {"level":"warn","ts":1592972186.9775953,"caller":"tesla-stats-collector/main.go:251","msg":"failed to query climate state for vehicle [redacted]","op":"main","error":"http status error: 408"}

So it got its first 408, and the result:

isaac@storage:~$ sudo lsof -p 3975729
COMMAND       PID  USER   FD      TYPE             DEVICE SIZE/OFF      NODE NAME
tesla-sta 3975729 isaac  cwd       DIR               0,28      244       256 /
tesla-sta 3975729 isaac  rtd       DIR               0,28      244       256 /
tesla-sta 3975729 isaac  txt       REG               0,28  8372334  46882240 /usr/local/bin/tesla-stats-collector
tesla-sta 3975729 isaac  mem       REG               0,26           46882240 /usr/local/bin/tesla-stats-collector (path dev=0,28)
tesla-sta 3975729 isaac  mem       REG               0,26           27771852 /lib/x86_64-linux-gnu/libresolv-2.31.so (path dev=0,28)
tesla-sta 3975729 isaac  mem       REG               0,26           27771845 /lib/x86_64-linux-gnu/libnss_dns-2.31.so (path dev=0,28)
tesla-sta 3975729 isaac  mem       REG               0,26           27771846 /lib/x86_64-linux-gnu/libnss_files-2.31.so (path dev=0,28)
tesla-sta 3975729 isaac  mem       REG               0,26           27771838 /lib/x86_64-linux-gnu/libc-2.31.so (path dev=0,28)
tesla-sta 3975729 isaac  mem       REG               0,26           27771851 /lib/x86_64-linux-gnu/libpthread-2.31.so (path dev=0,28)
tesla-sta 3975729 isaac  mem       REG               0,26           27771834 /lib/x86_64-linux-gnu/ld-2.31.so (path dev=0,28)
tesla-sta 3975729 isaac    0r      CHR                1,3      0t0         6 /dev/null
tesla-sta 3975729 isaac    1u     unix 0xffff9a60f3dd2800      0t0 200333439 type=STREAM
tesla-sta 3975729 isaac    2u     unix 0xffff9a60f3dd2800      0t0 200333439 type=STREAM
tesla-sta 3975729 isaac    3u     IPv4          200333446      0t0       TCP storage.mydomain:34086->205.234.31.120:https (ESTABLISHED)
tesla-sta 3975729 isaac    4u  a_inode               0,14        0     13476 [eventpoll]
tesla-sta 3975729 isaac    5u     IPv4          200332937      0t0       TCP storage.mydomain:34932->storage.mydomain:8086 (ESTABLISHED)
tesla-sta 3975729 isaac    6u     IPv4          200332142      0t0       TCP storage.mydomain:34124->205.234.31.120:https (ESTABLISHED)

You can see one additional connection to the API endpoint.

After some time passes:

isaac@storage:~$ sudo systemctl status tesla-stats-collector
● tesla-stats-collector.service - Poll Tesla vehicles and submit results to InfluxDB
     Loaded: loaded (/etc/systemd/system/tesla-stats-collector.service; enabled; vendor preset: enabled)
     Active: active (running) since Tue 2020-06-23 23:15:43 CDT; 4min 57s ago
   Main PID: 3975729 (tesla-stats-col)
      Tasks: 13 (limit: 38390)
     Memory: 7.7M
     CGroup: /system.slice/tesla-stats-collector.service
             └─3975729 /usr/local/bin/tesla-stats-collector -config /usr/local/etc/tesla-stats-collector/config.json

Jun 23 23:15:43 storage systemd[1]: Started Poll Tesla vehicles and submit results to InfluxDB.
Jun 23 23:16:26 storage tesla-stats-collector[3975729]: {"level":"warn","ts":1592972186.9775953,"caller":"tesla-stats-collector/main.go:251","msg":"failed to query climate state for vehicle [redacted]","op":"main","error":"http status error: 408"}
Jun 23 23:17:35 storage tesla-stats-collector[3975729]: {"level":"warn","ts":1592972255.1984704,"caller":"tesla-stats-collector/main.go:251","msg":"failed to query climate state for vehicle [redacted]","op":"main","error":"http status error: 408"}
Jun 23 23:17:58 storage tesla-stats-collector[3975729]: {"level":"warn","ts":1592972278.5269015,"caller":"tesla-stats-collector/main.go:251","msg":"failed to query climate state for vehicle [redacted]","op":"main","error":"http status error: 408"}
Jun 23 23:18:30 storage tesla-stats-collector[3975729]: {"level":"warn","ts":1592972310.310963,"caller":"tesla-stats-collector/main.go:241","msg":"failed to query charge state for vehicle [redacted]","op":"main","error":"http status error: 408"}
Jun 23 23:19:44 storage tesla-stats-collector[3975729]: {"level":"warn","ts":1592972384.7698622,"caller":"tesla-stats-collector/main.go:271","msg":"failed to query drive state for vehicle [redacted]","op":"main","error":"http status error: 408"}
Jun 23 23:20:14 storage tesla-stats-collector[3975729]: {"level":"warn","ts":1592972414.3573172,"caller":"tesla-stats-collector/main.go:271","msg":"failed to query drive state for vehicle [redacted]","op":"main","error":"http status error: 408"}
Jun 23 23:20:34 storage tesla-stats-collector[3975729]: {"level":"warn","ts":1592972434.0932143,"caller":"tesla-stats-collector/main.go:241","msg":"failed to query charge state for vehicle [redacted]","op":"main","error":"http status error: 408"}
isaac@storage:~$ sudo lsof -p 3975729
COMMAND       PID  USER   FD      TYPE             DEVICE SIZE/OFF      NODE NAME
tesla-sta 3975729 isaac  cwd       DIR               0,28      244       256 /
tesla-sta 3975729 isaac  rtd       DIR               0,28      244       256 /
tesla-sta 3975729 isaac  txt       REG               0,28  8372334  46882240 /usr/local/bin/tesla-stats-collector
tesla-sta 3975729 isaac  mem       REG               0,26           46882240 /usr/local/bin/tesla-stats-collector (path dev=0,28)
tesla-sta 3975729 isaac  mem       REG               0,26           27771852 /lib/x86_64-linux-gnu/libresolv-2.31.so (path dev=0,28)
tesla-sta 3975729 isaac  mem       REG               0,26           27771845 /lib/x86_64-linux-gnu/libnss_dns-2.31.so (path dev=0,28)
tesla-sta 3975729 isaac  mem       REG               0,26           27771846 /lib/x86_64-linux-gnu/libnss_files-2.31.so (path dev=0,28)
tesla-sta 3975729 isaac  mem       REG               0,26           27771838 /lib/x86_64-linux-gnu/libc-2.31.so (path dev=0,28)
tesla-sta 3975729 isaac  mem       REG               0,26           27771851 /lib/x86_64-linux-gnu/libpthread-2.31.so (path dev=0,28)
tesla-sta 3975729 isaac  mem       REG               0,26           27771834 /lib/x86_64-linux-gnu/ld-2.31.so (path dev=0,28)
tesla-sta 3975729 isaac    0r      CHR                1,3      0t0         6 /dev/null
tesla-sta 3975729 isaac    1u     unix 0xffff9a60f3dd2800      0t0 200333439 type=STREAM
tesla-sta 3975729 isaac    2u     unix 0xffff9a60f3dd2800      0t0 200333439 type=STREAM
tesla-sta 3975729 isaac    3u     IPv4          200333446      0t0       TCP storage.mydomain:34086->205.234.31.120:https (CLOSE_WAIT)
tesla-sta 3975729 isaac    4u  a_inode               0,14        0     13476 [eventpoll]
tesla-sta 3975729 isaac    5u     IPv4          200332937      0t0       TCP storage.mydomain:34932->storage.mydomain:8086 (ESTABLISHED)
tesla-sta 3975729 isaac    6u     IPv4          200332142      0t0       TCP storage.mydomain:34124->205.234.31.120:https (CLOSE_WAIT)
tesla-sta 3975729 isaac    7u     IPv4          200336192      0t0       TCP storage.mydomain:34170->205.234.31.120:https (CLOSE_WAIT)
tesla-sta 3975729 isaac    8u     IPv4          200347889      0t0       TCP storage.mydomain:34188->205.234.31.120:https (CLOSE_WAIT)
tesla-sta 3975729 isaac    9u     IPv4          200346457      0t0       TCP storage.mydomain:34212->205.234.31.120:https (ESTABLISHED)
tesla-sta 3975729 isaac   10u     IPv4          200361324      0t0       TCP storage.mydomain:34264->205.234.31.120:https (ESTABLISHED)
tesla-sta 3975729 isaac   11u     IPv4          200363108      0t0       TCP storage.mydomain:34286->205.234.31.120:https (ESTABLISHED)
tesla-sta 3975729 isaac   12u     IPv4          200355480      0t0       TCP storage.mydomain:34300->205.234.31.120:https (ESTABLISHED)

and you can see how this will become problematic.

Post-patch

Here is the same service running with this patch.

isaac@storage:~$ sudo systemctl status tesla-stats-collector                                                                                                                                                                                                           
● tesla-stats-collector.service - Poll Tesla vehicles and submit results to InfluxDB
     Loaded: loaded (/etc/systemd/system/tesla-stats-collector.service; enabled; vendor preset: enabled)
     Active: active (running) since Tue 2020-06-23 23:22:33 CDT; 7min ago
   Main PID: 225516 (tesla-stats-col)
      Tasks: 13 (limit: 38390)
     Memory: 7.9M
     CGroup: /system.slice/tesla-stats-collector.service
             └─225516 /usr/local/bin/tesla-stats-collector -config /usr/local/etc/tesla-stats-collector/config.json

Jun 23 23:22:33 storage systemd[1]: Started Poll Tesla vehicles and submit results to InfluxDB.
Jun 23 23:22:56 storage tesla-stats-collector[225516]: {"level":"warn","ts":1592972576.0198686,"caller":"tesla-stats-collector/main.go:251","msg":"failed to query climate state for vehicle [redacted]","op":"main","error":"http status error: 408"}          
Jun 23 23:23:39 storage tesla-stats-collector[225516]: {"level":"warn","ts":1592972619.315075,"caller":"tesla-stats-collector/main.go:271","msg":"failed to query drive state for vehicle [redacted]","op":"main","error":"http status error: 408"}             
Jun 23 23:26:08 storage tesla-stats-collector[225516]: {"level":"warn","ts":1592972768.8272288,"caller":"tesla-stats-collector/main.go:261","msg":"failed to query vehicle state for vehicle [redacted]","op":"main","error":"http status error: 408"}          
Jun 23 23:27:04 storage tesla-stats-collector[225516]: {"level":"warn","ts":1592972824.5369403,"caller":"tesla-stats-collector/main.go:271","msg":"failed to query drive state for vehicle [redacted]","op":"main","error":"http status error: 408"}            
Jun 23 23:27:20 storage tesla-stats-collector[225516]: {"level":"warn","ts":1592972840.0401983,"caller":"tesla-stats-collector/main.go:261","msg":"failed to query vehicle state for vehicle [redacted]","op":"main","error":"http status error: 408"}          
Jun 23 23:28:59 storage tesla-stats-collector[225516]: {"level":"warn","ts":1592972939.4939888,"caller":"tesla-stats-collector/main.go:261","msg":"failed to query vehicle state for vehicle [redacted]","op":"main","error":"http status error: 408"}   

We've gotten several 408's, but now...

isaac@storage:~$ sudo lsof -p 225516
COMMAND      PID  USER   FD      TYPE             DEVICE SIZE/OFF      NODE NAME
tesla-sta 225516 isaac  cwd       DIR               0,28      244       256 /
tesla-sta 225516 isaac  rtd       DIR               0,28      244       256 /
tesla-sta 225516 isaac  txt       REG               0,28  8385463  46882240 /usr/local/bin/tesla-stats-collector
tesla-sta 225516 isaac  mem       REG               0,26           46882240 /usr/local/bin/tesla-stats-collector (path dev=0,28)
tesla-sta 225516 isaac  mem       REG               0,26           27771852 /lib/x86_64-linux-gnu/libresolv-2.31.so (path dev=0,28)
tesla-sta 225516 isaac  mem       REG               0,26           27771845 /lib/x86_64-linux-gnu/libnss_dns-2.31.so (path dev=0,28)                                                                                                                                   
tesla-sta 225516 isaac  mem       REG               0,26           27771846 /lib/x86_64-linux-gnu/libnss_files-2.31.so (path dev=0,28)                                                                                                                                 
tesla-sta 225516 isaac  mem       REG               0,26           27771838 /lib/x86_64-linux-gnu/libc-2.31.so (path dev=0,28)
tesla-sta 225516 isaac  mem       REG               0,26           27771851 /lib/x86_64-linux-gnu/libpthread-2.31.so (path dev=0,28)                                                                                                                                   
tesla-sta 225516 isaac  mem       REG               0,26           27771834 /lib/x86_64-linux-gnu/ld-2.31.so (path dev=0,28)
tesla-sta 225516 isaac    0r      CHR                1,3      0t0         6 /dev/null
tesla-sta 225516 isaac    1u     unix 0xffff9a60eb384c00      0t0 200353732 type=STREAM
tesla-sta 225516 isaac    2u     unix 0xffff9a60eb384c00      0t0 200353732 type=STREAM
tesla-sta 225516 isaac    3u     IPv4          200416405      0t0       TCP storage.mydomain:34662->205.234.31.120:https (ESTABLISHED)                                                                                                                       
tesla-sta 225516 isaac    4u  a_inode               0,14        0     13476 [eventpoll]
tesla-sta 225516 isaac    5u     IPv4          200384109      0t0       TCP storage.mydomain:35220->storage.mydomain:8086 (ESTABLISHED)   

Much better.

rickbassham commented 4 years ago

Thanks for the catch!

iwvelando commented 4 years ago

@rickbassham will definitely squash commits when ready, thanks for the reminder there.

Regarding checking for a nil body, I checked the docs and I'm not certain that's a possibility:

$ go doc net/http.Response.Body
package http // import "net/http"

type Response struct {
    // Body represents the response body.
    // 
    // The response body is streamed on demand as the Body field is read. If the
    // network connection fails or the server terminates the response, Body.Read
    // calls return an error.
    // 
    // The http Client and Transport guarantee that Body is always non-nil, even on <-----------------
    // responses without a body or responses with a zero-length body. It is the
    // caller's responsibility to close Body. The default HTTP client's Transport
    // may not reuse HTTP/1.x "keep-alive" TCP connections if the Body is not read
    // to completion and closed.
    // 
    // The Body is automatically dechunked if the server replied with a "chunked"
    // Transfer-Encoding.
    // 
    // As of Go 1.12, the Body will also implement io.Writer on a successful "101
    // Switching Protocols" response, as used by WebSockets and HTTP/2's "h2c"
    // mode.
    Body io.ReadCloser

    // ... other fields elided ...
}

What do you think?

iwvelando commented 4 years ago

Ah right, I see your point. roundTrip itself can return a nil response in the event of certain errors, so we can check for that.

iwvelando commented 4 years ago

Applied nil check and squashed.

Testing method

According to https://golang.org/src/net/http/transport.go in roundTrip one early failure case that should result in a nil response and an error is an invalid scheme; I'll force failures by setting a bogus scheme. Also, it only returns a non-nil response if errors are nil, so I think it's sufficient to verify that the response is not nil (i.e. we don't also have to check -- after that -- that resp.Body is not nil).

Current Version With Induced Failure

I made this local patch:

$ git diff
diff --git a/conn.go b/conn.go
index 33f444a..2edaa30 100644
--- a/conn.go
+++ b/conn.go
@@ -84,6 +84,7 @@ func (c *Conn) doRequest(method, url string, reqBody, respBody interface{}) erro
                req.Header.Add("Authorization", fmt.Sprintf("Bearer %s", c.accessToken))
        }

+       req.URL.Scheme = "HT"
        resp, err := c.rt.RoundTrip(req)

        defer resp.Body.Close()

and rebuilt:

$ ./tesla-stats-collector 
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x40 pc=0x67f14a]

goroutine 1 [running]:
github.com/iwvelando/tesla.(*Conn).doRequest(0xc0000dbc50, 0x761b38, 0x4, 0x763a0c, 0xc, 0x6d70a0, 0xc00008e0f0, 0x6d7120, 0xc00005e540, 0x0, ...)
        /home/iwvelando/go/src/github.com/iwvelando/tesla/conn.go:90 +0x2aa
github.com/iwvelando/tesla.(*Conn).Authenticate(0xc0000dbc50, 0xc000018360, 0x13, 0xc000016740, 0xf, 0xc00001a217, 0x1f)
        /home/iwvelando/go/src/github.com/iwvelando/tesla/auth.go:42 +0x181
main.main()
        /home/iwvelando/go/src/github.com/iwvelando/tesla-stats-collector/main.go:164 +0x725

As you pointed out this needs to be covered.

Response-checked Version With Induced Failure

Now I made this local patch:

$ git diff
diff --git a/conn.go b/conn.go
index 33f444a..3866e3c 100644
--- a/conn.go
+++ b/conn.go
@@ -84,9 +84,12 @@ func (c *Conn) doRequest(method, url string, reqBody, respBody interface{}) erro
                req.Header.Add("Authorization", fmt.Sprintf("Bearer %s", c.accessToken))
        }

+       req.URL.Scheme = "HT"
        resp, err := c.rt.RoundTrip(req)

-       defer resp.Body.Close()
+       if resp != nil {
+               defer resp.Body.Close()
+       }

        if err != nil {
                return fmt.Errorf("error performing http request: %w", err)

Now after rebuilding:

$ ./tesla-stats-collector 
{"level":"fatal","ts":1593056337.2011576,"caller":"tesla-stats-collector/main.go:166","msg":"failed to connect to Tesla API","op":"main","error":"error performing http request: unsupported protocol scheme \"HT\"","stacktrace":"main.main\n\t/home/iwvelando/go/src/github.com/iwvelando/tesla-stats-collector/main.go:166\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:203"}

Response-checked Version Without Induced Failure

Finally we'll just leave in the response nil check:

$ git diff
diff --git a/conn.go b/conn.go
index 33f444a..67afbe5 100644
--- a/conn.go
+++ b/conn.go
@@ -86,7 +86,9 @@ func (c *Conn) doRequest(method, url string, reqBody, respBody interface{}) erro

        resp, err := c.rt.RoundTrip(req)

-       defer resp.Body.Close()
+       if resp != nil {
+               defer resp.Body.Close()
+       }

        if err != nil {
                return fmt.Errorf("error performing http request: %w", err)

Rebuild and add some debug output:

$ ./tesla-stats-collector 
[{vehicle_charge_state map[api_version:8...[redacted]
iwvelando commented 4 years ago

@rickbassham let me know what you think of the latest version or if you have any further requests. Thanks.

rickbassham commented 4 years ago

:tada: This PR is included in version 1.0.1 :tada:

The release is available on GitHub release

Your semantic-release bot :package::rocket: