github.com/timstclair/heapster@v0.20.0-alpha1/Godeps/_workspace/src/google.golang.org/appengine/internal/api.go (about) 1 // Copyright 2011 Google Inc. All rights reserved. 2 // Use of this source code is governed by the Apache 2.0 3 // license that can be found in the LICENSE file. 4 5 // +build !appengine 6 7 package internal 8 9 import ( 10 "bytes" 11 "errors" 12 "fmt" 13 "io/ioutil" 14 "log" 15 "net" 16 "net/http" 17 "net/url" 18 "os" 19 "runtime" 20 "strconv" 21 "strings" 22 "sync" 23 "sync/atomic" 24 "time" 25 26 "github.com/golang/protobuf/proto" 27 netcontext "golang.org/x/net/context" 28 29 basepb "google.golang.org/appengine/internal/base" 30 logpb "google.golang.org/appengine/internal/log" 31 remotepb "google.golang.org/appengine/internal/remote_api" 32 ) 33 34 const ( 35 apiPath = "/rpc_http" 36 ) 37 38 var ( 39 // Incoming headers. 40 ticketHeader = http.CanonicalHeaderKey("X-AppEngine-API-Ticket") 41 dapperHeader = http.CanonicalHeaderKey("X-Google-DapperTraceInfo") 42 traceHeader = http.CanonicalHeaderKey("X-Cloud-Trace-Context") 43 curNamespaceHeader = http.CanonicalHeaderKey("X-AppEngine-Current-Namespace") 44 userIPHeader = http.CanonicalHeaderKey("X-AppEngine-User-IP") 45 remoteAddrHeader = http.CanonicalHeaderKey("X-AppEngine-Remote-Addr") 46 47 // Outgoing headers. 48 apiEndpointHeader = http.CanonicalHeaderKey("X-Google-RPC-Service-Endpoint") 49 apiEndpointHeaderValue = []string{"app-engine-apis"} 50 apiMethodHeader = http.CanonicalHeaderKey("X-Google-RPC-Service-Method") 51 apiMethodHeaderValue = []string{"/VMRemoteAPI.CallRemoteAPI"} 52 apiDeadlineHeader = http.CanonicalHeaderKey("X-Google-RPC-Service-Deadline") 53 apiContentType = http.CanonicalHeaderKey("Content-Type") 54 apiContentTypeValue = []string{"application/octet-stream"} 55 logFlushHeader = http.CanonicalHeaderKey("X-AppEngine-Log-Flush-Count") 56 57 apiHTTPClient = &http.Client{ 58 Transport: &http.Transport{ 59 Proxy: http.ProxyFromEnvironment, 60 Dial: limitDial, 61 }, 62 } 63 ) 64 65 func apiURL() *url.URL { 66 host, port := "appengine.googleapis.internal", "10001" 67 if h := os.Getenv("API_HOST"); h != "" { 68 host = h 69 } 70 if p := os.Getenv("API_PORT"); p != "" { 71 port = p 72 } 73 return &url.URL{ 74 Scheme: "http", 75 Host: host + ":" + port, 76 Path: apiPath, 77 } 78 } 79 80 func handleHTTP(w http.ResponseWriter, r *http.Request) { 81 c := &context{ 82 req: r, 83 outHeader: w.Header(), 84 apiURL: apiURL(), 85 } 86 stopFlushing := make(chan int) 87 88 ctxs.Lock() 89 ctxs.m[r] = c 90 ctxs.Unlock() 91 defer func() { 92 ctxs.Lock() 93 delete(ctxs.m, r) 94 ctxs.Unlock() 95 }() 96 97 // Patch up RemoteAddr so it looks reasonable. 98 if addr := r.Header.Get(userIPHeader); addr != "" { 99 r.RemoteAddr = addr 100 } else if addr = r.Header.Get(remoteAddrHeader); addr != "" { 101 r.RemoteAddr = addr 102 } else { 103 // Should not normally reach here, but pick a sensible default anyway. 104 r.RemoteAddr = "127.0.0.1" 105 } 106 // The address in the headers will most likely be of these forms: 107 // 123.123.123.123 108 // 2001:db8::1 109 // net/http.Request.RemoteAddr is specified to be in "IP:port" form. 110 if _, _, err := net.SplitHostPort(r.RemoteAddr); err != nil { 111 // Assume the remote address is only a host; add a default port. 112 r.RemoteAddr = net.JoinHostPort(r.RemoteAddr, "80") 113 } 114 115 // Start goroutine responsible for flushing app logs. 116 // This is done after adding c to ctx.m (and stopped before removing it) 117 // because flushing logs requires making an API call. 118 go c.logFlusher(stopFlushing) 119 120 executeRequestSafely(c, r) 121 c.outHeader = nil // make sure header changes aren't respected any more 122 123 stopFlushing <- 1 // any logging beyond this point will be dropped 124 125 // Flush any pending logs asynchronously. 126 c.pendingLogs.Lock() 127 flushes := c.pendingLogs.flushes 128 if len(c.pendingLogs.lines) > 0 { 129 flushes++ 130 } 131 c.pendingLogs.Unlock() 132 go c.flushLog(false) 133 w.Header().Set(logFlushHeader, strconv.Itoa(flushes)) 134 135 // Avoid nil Write call if c.Write is never called. 136 if c.outCode != 0 { 137 w.WriteHeader(c.outCode) 138 } 139 if c.outBody != nil { 140 w.Write(c.outBody) 141 } 142 } 143 144 func executeRequestSafely(c *context, r *http.Request) { 145 defer func() { 146 if x := recover(); x != nil { 147 logf(c, 4, "%s", renderPanic(x)) // 4 == critical 148 c.outCode = 500 149 } 150 }() 151 152 http.DefaultServeMux.ServeHTTP(c, r) 153 } 154 155 func renderPanic(x interface{}) string { 156 buf := make([]byte, 16<<10) // 16 KB should be plenty 157 buf = buf[:runtime.Stack(buf, false)] 158 159 // Remove the first few stack frames: 160 // this func 161 // the recover closure in the caller 162 // That will root the stack trace at the site of the panic. 163 const ( 164 skipStart = "internal.renderPanic" 165 skipFrames = 2 166 ) 167 start := bytes.Index(buf, []byte(skipStart)) 168 p := start 169 for i := 0; i < skipFrames*2 && p+1 < len(buf); i++ { 170 p = bytes.IndexByte(buf[p+1:], '\n') + p + 1 171 if p < 0 { 172 break 173 } 174 } 175 if p >= 0 { 176 // buf[start:p+1] is the block to remove. 177 // Copy buf[p+1:] over buf[start:] and shrink buf. 178 copy(buf[start:], buf[p+1:]) 179 buf = buf[:len(buf)-(p+1-start)] 180 } 181 182 // Add panic heading. 183 head := fmt.Sprintf("panic: %v\n\n", x) 184 if len(head) > len(buf) { 185 // Extremely unlikely to happen. 186 return head 187 } 188 copy(buf[len(head):], buf) 189 copy(buf, head) 190 191 return string(buf) 192 } 193 194 var ctxs = struct { 195 sync.Mutex 196 m map[*http.Request]*context 197 bg *context // background context, lazily initialized 198 // dec is used by tests to decorate the netcontext.Context returned 199 // for a given request. This allows tests to add overrides (such as 200 // WithAppIDOverride) to the context. The map is nil outside tests. 201 dec map[*http.Request]func(netcontext.Context) netcontext.Context 202 }{ 203 m: make(map[*http.Request]*context), 204 } 205 206 // context represents the context of an in-flight HTTP request. 207 // It implements the appengine.Context and http.ResponseWriter interfaces. 208 type context struct { 209 req *http.Request 210 211 outCode int 212 outHeader http.Header 213 outBody []byte 214 215 pendingLogs struct { 216 sync.Mutex 217 lines []*logpb.UserAppLogLine 218 flushes int 219 } 220 221 apiURL *url.URL 222 } 223 224 var contextKey = "holds a *context" 225 226 func fromContext(ctx netcontext.Context) *context { 227 c, _ := ctx.Value(&contextKey).(*context) 228 return c 229 } 230 231 func withContext(parent netcontext.Context, c *context) netcontext.Context { 232 ctx := netcontext.WithValue(parent, &contextKey, c) 233 if ns := c.req.Header.Get(curNamespaceHeader); ns != "" { 234 ctx = withNamespace(ctx, ns) 235 } 236 return ctx 237 } 238 239 func toContext(c *context) netcontext.Context { 240 return withContext(netcontext.Background(), c) 241 } 242 243 func IncomingHeaders(ctx netcontext.Context) http.Header { 244 if c := fromContext(ctx); c != nil { 245 return c.req.Header 246 } 247 return nil 248 } 249 250 func WithContext(parent netcontext.Context, req *http.Request) netcontext.Context { 251 ctxs.Lock() 252 c := ctxs.m[req] 253 d := ctxs.dec[req] 254 ctxs.Unlock() 255 256 if d != nil { 257 parent = d(parent) 258 } 259 260 if c == nil { 261 // Someone passed in an http.Request that is not in-flight. 262 // We panic here rather than panicking at a later point 263 // so that stack traces will be more sensible. 264 log.Panic("appengine: NewContext passed an unknown http.Request") 265 } 266 return withContext(parent, c) 267 } 268 269 func BackgroundContext() netcontext.Context { 270 ctxs.Lock() 271 defer ctxs.Unlock() 272 273 if ctxs.bg != nil { 274 return toContext(ctxs.bg) 275 } 276 277 // Compute background security ticket. 278 appID := partitionlessAppID() 279 escAppID := strings.Replace(strings.Replace(appID, ":", "_", -1), ".", "_", -1) 280 majVersion := VersionID(nil) 281 if i := strings.Index(majVersion, "."); i > 0 { 282 majVersion = majVersion[:i] 283 } 284 ticket := fmt.Sprintf("%s/%s.%s.%s", escAppID, ModuleName(nil), majVersion, InstanceID()) 285 286 ctxs.bg = &context{ 287 req: &http.Request{ 288 Header: http.Header{ 289 ticketHeader: []string{ticket}, 290 }, 291 }, 292 apiURL: apiURL(), 293 } 294 295 // TODO(dsymonds): Wire up the shutdown handler to do a final flush. 296 go ctxs.bg.logFlusher(make(chan int)) 297 298 return toContext(ctxs.bg) 299 } 300 301 // RegisterTestRequest registers the HTTP request req for testing, such that 302 // any API calls are sent to the provided URL. It returns a closure to delete 303 // the registration. 304 // It should only be used by aetest package. 305 func RegisterTestRequest(req *http.Request, apiURL *url.URL, decorate func(netcontext.Context) netcontext.Context) func() { 306 c := &context{ 307 req: req, 308 apiURL: apiURL, 309 } 310 ctxs.Lock() 311 defer ctxs.Unlock() 312 if _, ok := ctxs.m[req]; ok { 313 log.Panic("req already associated with context") 314 } 315 if _, ok := ctxs.dec[req]; ok { 316 log.Panic("req already associated with context") 317 } 318 if ctxs.dec == nil { 319 ctxs.dec = make(map[*http.Request]func(netcontext.Context) netcontext.Context) 320 } 321 ctxs.m[req] = c 322 ctxs.dec[req] = decorate 323 324 return func() { 325 ctxs.Lock() 326 delete(ctxs.m, req) 327 delete(ctxs.dec, req) 328 ctxs.Unlock() 329 } 330 } 331 332 var errTimeout = &CallError{ 333 Detail: "Deadline exceeded", 334 Code: int32(remotepb.RpcError_CANCELLED), 335 Timeout: true, 336 } 337 338 func (c *context) Header() http.Header { return c.outHeader } 339 340 // Copied from $GOROOT/src/pkg/net/http/transfer.go. Some response status 341 // codes do not permit a response body (nor response entity headers such as 342 // Content-Length, Content-Type, etc). 343 func bodyAllowedForStatus(status int) bool { 344 switch { 345 case status >= 100 && status <= 199: 346 return false 347 case status == 204: 348 return false 349 case status == 304: 350 return false 351 } 352 return true 353 } 354 355 func (c *context) Write(b []byte) (int, error) { 356 if c.outCode == 0 { 357 c.WriteHeader(http.StatusOK) 358 } 359 if len(b) > 0 && !bodyAllowedForStatus(c.outCode) { 360 return 0, http.ErrBodyNotAllowed 361 } 362 c.outBody = append(c.outBody, b...) 363 return len(b), nil 364 } 365 366 func (c *context) WriteHeader(code int) { 367 if c.outCode != 0 { 368 logf(c, 3, "WriteHeader called multiple times on request.") // error level 369 return 370 } 371 c.outCode = code 372 } 373 374 func (c *context) post(body []byte, timeout time.Duration) (b []byte, err error) { 375 hreq := &http.Request{ 376 Method: "POST", 377 URL: c.apiURL, 378 Header: http.Header{ 379 apiEndpointHeader: apiEndpointHeaderValue, 380 apiMethodHeader: apiMethodHeaderValue, 381 apiContentType: apiContentTypeValue, 382 apiDeadlineHeader: []string{strconv.FormatFloat(timeout.Seconds(), 'f', -1, 64)}, 383 }, 384 Body: ioutil.NopCloser(bytes.NewReader(body)), 385 ContentLength: int64(len(body)), 386 Host: c.apiURL.Host, 387 } 388 if info := c.req.Header.Get(dapperHeader); info != "" { 389 hreq.Header.Set(dapperHeader, info) 390 } 391 if info := c.req.Header.Get(traceHeader); info != "" { 392 hreq.Header.Set(traceHeader, info) 393 } 394 395 tr := apiHTTPClient.Transport.(*http.Transport) 396 397 var timedOut int32 // atomic; set to 1 if timed out 398 t := time.AfterFunc(timeout, func() { 399 atomic.StoreInt32(&timedOut, 1) 400 tr.CancelRequest(hreq) 401 }) 402 defer t.Stop() 403 defer func() { 404 // Check if timeout was exceeded. 405 if atomic.LoadInt32(&timedOut) != 0 { 406 err = errTimeout 407 } 408 }() 409 410 hresp, err := apiHTTPClient.Do(hreq) 411 if err != nil { 412 return nil, &CallError{ 413 Detail: fmt.Sprintf("service bridge HTTP failed: %v", err), 414 Code: int32(remotepb.RpcError_UNKNOWN), 415 } 416 } 417 defer hresp.Body.Close() 418 hrespBody, err := ioutil.ReadAll(hresp.Body) 419 if hresp.StatusCode != 200 { 420 return nil, &CallError{ 421 Detail: fmt.Sprintf("service bridge returned HTTP %d (%q)", hresp.StatusCode, hrespBody), 422 Code: int32(remotepb.RpcError_UNKNOWN), 423 } 424 } 425 if err != nil { 426 return nil, &CallError{ 427 Detail: fmt.Sprintf("service bridge response bad: %v", err), 428 Code: int32(remotepb.RpcError_UNKNOWN), 429 } 430 } 431 return hrespBody, nil 432 } 433 434 func Call(ctx netcontext.Context, service, method string, in, out proto.Message) error { 435 if f, ctx, ok := callOverrideFromContext(ctx); ok { 436 return f(ctx, service, method, in, out) 437 } 438 439 // Handle already-done contexts quickly. 440 select { 441 case <-ctx.Done(): 442 return ctx.Err() 443 default: 444 } 445 446 c := fromContext(ctx) 447 if c == nil { 448 // Give a good error message rather than a panic lower down. 449 return errors.New("not an App Engine context") 450 } 451 452 // Apply transaction modifications if we're in a transaction. 453 if t := transactionFromContext(ctx); t != nil { 454 if t.finished { 455 return errors.New("transaction context has expired") 456 } 457 applyTransaction(in, &t.transaction) 458 } 459 460 // Default RPC timeout is 60s. 461 timeout := 60 * time.Second 462 if deadline, ok := ctx.Deadline(); ok { 463 timeout = deadline.Sub(time.Now()) 464 } 465 466 data, err := proto.Marshal(in) 467 if err != nil { 468 return err 469 } 470 471 ticket := c.req.Header.Get(ticketHeader) 472 req := &remotepb.Request{ 473 ServiceName: &service, 474 Method: &method, 475 Request: data, 476 RequestId: &ticket, 477 } 478 hreqBody, err := proto.Marshal(req) 479 if err != nil { 480 return err 481 } 482 483 hrespBody, err := c.post(hreqBody, timeout) 484 if err != nil { 485 return err 486 } 487 488 res := &remotepb.Response{} 489 if err := proto.Unmarshal(hrespBody, res); err != nil { 490 return err 491 } 492 if res.RpcError != nil { 493 ce := &CallError{ 494 Detail: res.RpcError.GetDetail(), 495 Code: *res.RpcError.Code, 496 } 497 switch remotepb.RpcError_ErrorCode(ce.Code) { 498 case remotepb.RpcError_CANCELLED, remotepb.RpcError_DEADLINE_EXCEEDED: 499 ce.Timeout = true 500 } 501 return ce 502 } 503 if res.ApplicationError != nil { 504 return &APIError{ 505 Service: *req.ServiceName, 506 Detail: res.ApplicationError.GetDetail(), 507 Code: *res.ApplicationError.Code, 508 } 509 } 510 if res.Exception != nil || res.JavaException != nil { 511 // This shouldn't happen, but let's be defensive. 512 return &CallError{ 513 Detail: "service bridge returned exception", 514 Code: int32(remotepb.RpcError_UNKNOWN), 515 } 516 } 517 return proto.Unmarshal(res.Response, out) 518 } 519 520 func (c *context) Request() *http.Request { 521 return c.req 522 } 523 524 func (c *context) addLogLine(ll *logpb.UserAppLogLine) { 525 // Truncate long log lines. 526 // TODO(dsymonds): Check if this is still necessary. 527 const lim = 8 << 10 528 if len(*ll.Message) > lim { 529 suffix := fmt.Sprintf("...(length %d)", len(*ll.Message)) 530 ll.Message = proto.String((*ll.Message)[:lim-len(suffix)] + suffix) 531 } 532 533 c.pendingLogs.Lock() 534 c.pendingLogs.lines = append(c.pendingLogs.lines, ll) 535 c.pendingLogs.Unlock() 536 } 537 538 var logLevelName = map[int64]string{ 539 0: "DEBUG", 540 1: "INFO", 541 2: "WARNING", 542 3: "ERROR", 543 4: "CRITICAL", 544 } 545 546 func logf(c *context, level int64, format string, args ...interface{}) { 547 s := fmt.Sprintf(format, args...) 548 s = strings.TrimRight(s, "\n") // Remove any trailing newline characters. 549 c.addLogLine(&logpb.UserAppLogLine{ 550 TimestampUsec: proto.Int64(time.Now().UnixNano() / 1e3), 551 Level: &level, 552 Message: &s, 553 }) 554 log.Print(logLevelName[level] + ": " + s) 555 } 556 557 // flushLog attempts to flush any pending logs to the appserver. 558 // It should not be called concurrently. 559 func (c *context) flushLog(force bool) (flushed bool) { 560 c.pendingLogs.Lock() 561 // Grab up to 30 MB. We can get away with up to 32 MB, but let's be cautious. 562 n, rem := 0, 30<<20 563 for ; n < len(c.pendingLogs.lines); n++ { 564 ll := c.pendingLogs.lines[n] 565 // Each log line will require about 3 bytes of overhead. 566 nb := proto.Size(ll) + 3 567 if nb > rem { 568 break 569 } 570 rem -= nb 571 } 572 lines := c.pendingLogs.lines[:n] 573 c.pendingLogs.lines = c.pendingLogs.lines[n:] 574 c.pendingLogs.Unlock() 575 576 if len(lines) == 0 && !force { 577 // Nothing to flush. 578 return false 579 } 580 581 rescueLogs := false 582 defer func() { 583 if rescueLogs { 584 c.pendingLogs.Lock() 585 c.pendingLogs.lines = append(lines, c.pendingLogs.lines...) 586 c.pendingLogs.Unlock() 587 } 588 }() 589 590 buf, err := proto.Marshal(&logpb.UserAppLogGroup{ 591 LogLine: lines, 592 }) 593 if err != nil { 594 log.Printf("internal.flushLog: marshaling UserAppLogGroup: %v", err) 595 rescueLogs = true 596 return false 597 } 598 599 req := &logpb.FlushRequest{ 600 Logs: buf, 601 } 602 res := &basepb.VoidProto{} 603 c.pendingLogs.Lock() 604 c.pendingLogs.flushes++ 605 c.pendingLogs.Unlock() 606 if err := Call(toContext(c), "logservice", "Flush", req, res); err != nil { 607 log.Printf("internal.flushLog: Flush RPC: %v", err) 608 rescueLogs = true 609 return false 610 } 611 return true 612 } 613 614 const ( 615 // Log flushing parameters. 616 flushInterval = 1 * time.Second 617 forceFlushInterval = 60 * time.Second 618 ) 619 620 func (c *context) logFlusher(stop <-chan int) { 621 lastFlush := time.Now() 622 tick := time.NewTicker(flushInterval) 623 for { 624 select { 625 case <-stop: 626 // Request finished. 627 tick.Stop() 628 return 629 case <-tick.C: 630 force := time.Now().Sub(lastFlush) > forceFlushInterval 631 if c.flushLog(force) { 632 lastFlush = time.Now() 633 } 634 } 635 } 636 } 637 638 func ContextForTesting(req *http.Request) netcontext.Context { 639 return toContext(&context{req: req}) 640 }