11407: keepclient checks for ARVADOS_DEBUG and enables debugging.
[arvados.git] / sdk / go / keepclient / support.go
1 package keepclient
2
3 import (
4         "crypto/md5"
5         "errors"
6         "fmt"
7         "git.curoverse.com/arvados.git/sdk/go/streamer"
8         "io"
9         "io/ioutil"
10         "log"
11         "math/rand"
12         "net"
13         "net/http"
14         "os"
15         "regexp"
16         "strings"
17         "time"
18 )
19
20 // Function used to emit debug messages. The easiest way to enable
21 // keepclient debug messages in your application is to assign
22 // log.Printf to DebugPrintf.
23 var DebugPrintf = func(string, ...interface{}) {}
24
25 func init() {
26         var matchTrue = regexp.MustCompile("^(?i:1|yes|true)$")
27         if matchTrue.MatchString(os.Getenv("ARVADOS_DEBUG")) {
28                 DebugPrintf = log.Printf
29         }
30 }
31
32 type keepService struct {
33         Uuid     string `json:"uuid"`
34         Hostname string `json:"service_host"`
35         Port     int    `json:"service_port"`
36         SSL      bool   `json:"service_ssl_flag"`
37         SvcType  string `json:"service_type"`
38         ReadOnly bool   `json:"read_only"`
39 }
40
41 // Md5String returns md5 hash for the bytes in the given string
42 func Md5String(s string) string {
43         return fmt.Sprintf("%x", md5.Sum([]byte(s)))
44 }
45
46 // Set timeouts applicable when connecting to non-disk services
47 // (assumed to be over the Internet).
48 func (this *KeepClient) setClientSettingsNonDisk() {
49         if this.Client.Timeout == 0 {
50                 // Maximum time to wait for a complete response
51                 this.Client.Timeout = 300 * time.Second
52
53                 // TCP and TLS connection settings
54                 this.Client.Transport = &http.Transport{
55                         Dial: (&net.Dialer{
56                                 // The maximum time to wait to set up
57                                 // the initial TCP connection.
58                                 Timeout: 30 * time.Second,
59
60                                 // The TCP keep alive heartbeat
61                                 // interval.
62                                 KeepAlive: 120 * time.Second,
63                         }).Dial,
64
65                         TLSHandshakeTimeout: 10 * time.Second,
66                 }
67         }
68 }
69
70 // Set timeouts applicable when connecting to keepstore services directly
71 // (assumed to be on the local network).
72 func (this *KeepClient) setClientSettingsDisk() {
73         if this.Client.Timeout == 0 {
74                 // Maximum time to wait for a complete response
75                 this.Client.Timeout = 20 * time.Second
76
77                 // TCP and TLS connection timeouts
78                 this.Client.Transport = &http.Transport{
79                         Dial: (&net.Dialer{
80                                 // The maximum time to wait to set up
81                                 // the initial TCP connection.
82                                 Timeout: 2 * time.Second,
83
84                                 // The TCP keep alive heartbeat
85                                 // interval.
86                                 KeepAlive: 180 * time.Second,
87                         }).Dial,
88
89                         TLSHandshakeTimeout: 4 * time.Second,
90                 }
91         }
92 }
93
94 type svcList struct {
95         Items []keepService `json:"items"`
96 }
97
98 type uploadStatus struct {
99         err             error
100         url             string
101         statusCode      int
102         replicas_stored int
103         response        string
104 }
105
106 func (this *KeepClient) uploadToKeepServer(host string, hash string, body io.ReadCloser,
107         upload_status chan<- uploadStatus, expectedLength int64, requestID int32) {
108
109         var req *http.Request
110         var err error
111         var url = fmt.Sprintf("%s/%s", host, hash)
112         if req, err = http.NewRequest("PUT", url, nil); err != nil {
113                 DebugPrintf("DEBUG: [%08x] Error creating request PUT %v error: %v", requestID, url, err.Error())
114                 upload_status <- uploadStatus{err, url, 0, 0, ""}
115                 body.Close()
116                 return
117         }
118
119         req.ContentLength = expectedLength
120         if expectedLength > 0 {
121                 // http.Client.Do will close the body ReadCloser when it is
122                 // done with it.
123                 req.Body = body
124         } else {
125                 // "For client requests, a value of 0 means unknown if Body is
126                 // not nil."  In this case we do want the body to be empty, so
127                 // don't set req.Body.  However, we still need to close the
128                 // body ReadCloser.
129                 body.Close()
130         }
131
132         req.Header.Add("Authorization", fmt.Sprintf("OAuth2 %s", this.Arvados.ApiToken))
133         req.Header.Add("Content-Type", "application/octet-stream")
134         req.Header.Add(X_Keep_Desired_Replicas, fmt.Sprint(this.Want_replicas))
135
136         var resp *http.Response
137         if resp, err = this.Client.Do(req); err != nil {
138                 DebugPrintf("DEBUG: [%08x] Upload failed %v error: %v", requestID, url, err.Error())
139                 upload_status <- uploadStatus{err, url, 0, 0, ""}
140                 return
141         }
142
143         rep := 1
144         if xr := resp.Header.Get(X_Keep_Replicas_Stored); xr != "" {
145                 fmt.Sscanf(xr, "%d", &rep)
146         }
147
148         defer resp.Body.Close()
149         defer io.Copy(ioutil.Discard, resp.Body)
150
151         respbody, err2 := ioutil.ReadAll(&io.LimitedReader{R: resp.Body, N: 4096})
152         response := strings.TrimSpace(string(respbody))
153         if err2 != nil && err2 != io.EOF {
154                 DebugPrintf("DEBUG: [%08x] Upload %v error: %v response: %v", requestID, url, err2.Error(), response)
155                 upload_status <- uploadStatus{err2, url, resp.StatusCode, rep, response}
156         } else if resp.StatusCode == http.StatusOK {
157                 DebugPrintf("DEBUG: [%08x] Upload %v success", requestID, url)
158                 upload_status <- uploadStatus{nil, url, resp.StatusCode, rep, response}
159         } else {
160                 DebugPrintf("DEBUG: [%08x] Upload %v error: %v response: %v", requestID, url, resp.StatusCode, response)
161                 upload_status <- uploadStatus{errors.New(resp.Status), url, resp.StatusCode, rep, response}
162         }
163 }
164
165 func (this *KeepClient) putReplicas(
166         hash string,
167         tr *streamer.AsyncStream,
168         expectedLength int64) (locator string, replicas int, err error) {
169
170         // Generate an arbitrary ID to identify this specific
171         // transaction in debug logs.
172         requestID := rand.Int31()
173
174         // Calculate the ordering for uploading to servers
175         sv := NewRootSorter(this.WritableLocalRoots(), hash).GetSortedRoots()
176
177         // The next server to try contacting
178         next_server := 0
179
180         // The number of active writers
181         active := 0
182
183         // Used to communicate status from the upload goroutines
184         upload_status := make(chan uploadStatus)
185         defer func() {
186                 // Wait for any abandoned uploads (e.g., we started
187                 // two uploads and the first replied with replicas=2)
188                 // to finish before closing the status channel.
189                 go func() {
190                         for active > 0 {
191                                 <-upload_status
192                         }
193                         close(upload_status)
194                 }()
195         }()
196
197         replicasDone := 0
198         replicasTodo := this.Want_replicas
199
200         replicasPerThread := this.replicasPerService
201         if replicasPerThread < 1 {
202                 // unlimited or unknown
203                 replicasPerThread = replicasTodo
204         }
205
206         retriesRemaining := 1 + this.Retries
207         var retryServers []string
208
209         for retriesRemaining > 0 {
210                 retriesRemaining -= 1
211                 next_server = 0
212                 retryServers = []string{}
213                 for replicasTodo > 0 {
214                         for active*replicasPerThread < replicasTodo {
215                                 // Start some upload requests
216                                 if next_server < len(sv) {
217                                         DebugPrintf("DEBUG: [%08x] Begin upload %s to %s", requestID, hash, sv[next_server])
218                                         go this.uploadToKeepServer(sv[next_server], hash, tr.MakeStreamReader(), upload_status, expectedLength, requestID)
219                                         next_server += 1
220                                         active += 1
221                                 } else {
222                                         if active == 0 && retriesRemaining == 0 {
223                                                 return locator, replicasDone, InsufficientReplicasError
224                                         } else {
225                                                 break
226                                         }
227                                 }
228                         }
229                         DebugPrintf("DEBUG: [%08x] Replicas remaining to write: %v active uploads: %v",
230                                 requestID, replicasTodo, active)
231
232                         // Now wait for something to happen.
233                         if active > 0 {
234                                 status := <-upload_status
235                                 active -= 1
236
237                                 if status.statusCode == 200 {
238                                         // good news!
239                                         replicasDone += status.replicas_stored
240                                         replicasTodo -= status.replicas_stored
241                                         locator = status.response
242                                 } else if status.statusCode == 0 || status.statusCode == 408 || status.statusCode == 429 ||
243                                         (status.statusCode >= 500 && status.statusCode != 503) {
244                                         // Timeout, too many requests, or other server side failure
245                                         // Do not retry when status code is 503, which means the keep server is full
246                                         retryServers = append(retryServers, status.url[0:strings.LastIndex(status.url, "/")])
247                                 }
248                         } else {
249                                 break
250                         }
251                 }
252
253                 sv = retryServers
254         }
255
256         return locator, replicasDone, nil
257 }