1// Copyright 2014 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
7package internal
8
9import (
10	"bufio"
11	"bytes"
12	"fmt"
13	"io"
14	"io/ioutil"
15	"net/http"
16	"net/http/httptest"
17	"net/url"
18	"os"
19	"os/exec"
20	"strings"
21	"sync/atomic"
22	"testing"
23	"time"
24
25	"github.com/golang/protobuf/proto"
26	netcontext "golang.org/x/net/context"
27
28	basepb "google.golang.org/appengine/internal/base"
29	remotepb "google.golang.org/appengine/internal/remote_api"
30)
31
32const testTicketHeader = "X-Magic-Ticket-Header"
33
34func init() {
35	ticketHeader = testTicketHeader
36}
37
38type fakeAPIHandler struct {
39	hang chan int // used for RunSlowly RPC
40
41	LogFlushes int32 // atomic
42}
43
44func (f *fakeAPIHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
45	writeResponse := func(res *remotepb.Response) {
46		hresBody, err := proto.Marshal(res)
47		if err != nil {
48			http.Error(w, fmt.Sprintf("Failed encoding API response: %v", err), 500)
49			return
50		}
51		w.Write(hresBody)
52	}
53
54	if r.URL.Path != "/rpc_http" {
55		http.NotFound(w, r)
56		return
57	}
58	hreqBody, err := ioutil.ReadAll(r.Body)
59	if err != nil {
60		http.Error(w, fmt.Sprintf("Bad body: %v", err), 500)
61		return
62	}
63	apiReq := &remotepb.Request{}
64	if err := proto.Unmarshal(hreqBody, apiReq); err != nil {
65		http.Error(w, fmt.Sprintf("Bad encoded API request: %v", err), 500)
66		return
67	}
68	if *apiReq.RequestId != "s3cr3t" && *apiReq.RequestId != DefaultTicket() {
69		writeResponse(&remotepb.Response{
70			RpcError: &remotepb.RpcError{
71				Code:   proto.Int32(int32(remotepb.RpcError_SECURITY_VIOLATION)),
72				Detail: proto.String("bad security ticket"),
73			},
74		})
75		return
76	}
77	if got, want := r.Header.Get(dapperHeader), "trace-001"; got != want {
78		writeResponse(&remotepb.Response{
79			RpcError: &remotepb.RpcError{
80				Code:   proto.Int32(int32(remotepb.RpcError_BAD_REQUEST)),
81				Detail: proto.String(fmt.Sprintf("trace info = %q, want %q", got, want)),
82			},
83		})
84		return
85	}
86
87	service, method := *apiReq.ServiceName, *apiReq.Method
88	var resOut proto.Message
89	if service == "actordb" && method == "LookupActor" {
90		req := &basepb.StringProto{}
91		res := &basepb.StringProto{}
92		if err := proto.Unmarshal(apiReq.Request, req); err != nil {
93			http.Error(w, fmt.Sprintf("Bad encoded request: %v", err), 500)
94			return
95		}
96		if *req.Value == "Doctor Who" {
97			res.Value = proto.String("David Tennant")
98		}
99		resOut = res
100	}
101	if service == "errors" {
102		switch method {
103		case "Non200":
104			http.Error(w, "I'm a little teapot.", 418)
105			return
106		case "ShortResponse":
107			w.Header().Set("Content-Length", "100")
108			w.Write([]byte("way too short"))
109			return
110		case "OverQuota":
111			writeResponse(&remotepb.Response{
112				RpcError: &remotepb.RpcError{
113					Code:   proto.Int32(int32(remotepb.RpcError_OVER_QUOTA)),
114					Detail: proto.String("you are hogging the resources!"),
115				},
116			})
117			return
118		case "RunSlowly":
119			// TestAPICallRPCFailure creates f.hang, but does not strobe it
120			// until Call returns with remotepb.RpcError_CANCELLED.
121			// This is here to force a happens-before relationship between
122			// the httptest server handler and shutdown.
123			<-f.hang
124			resOut = &basepb.VoidProto{}
125		}
126	}
127	if service == "logservice" && method == "Flush" {
128		// Pretend log flushing is slow.
129		time.Sleep(50 * time.Millisecond)
130		atomic.AddInt32(&f.LogFlushes, 1)
131		resOut = &basepb.VoidProto{}
132	}
133
134	encOut, err := proto.Marshal(resOut)
135	if err != nil {
136		http.Error(w, fmt.Sprintf("Failed encoding response: %v", err), 500)
137		return
138	}
139	writeResponse(&remotepb.Response{
140		Response: encOut,
141	})
142}
143
144func setup() (f *fakeAPIHandler, c *context, cleanup func()) {
145	f = &fakeAPIHandler{}
146	srv := httptest.NewServer(f)
147	u, err := url.Parse(srv.URL + apiPath)
148	if err != nil {
149		panic(fmt.Sprintf("url.Parse(%q): %v", srv.URL+apiPath, err))
150	}
151	return f, &context{
152		req: &http.Request{
153			Header: http.Header{
154				ticketHeader: []string{"s3cr3t"},
155				dapperHeader: []string{"trace-001"},
156			},
157		},
158		apiURL: u,
159	}, srv.Close
160}
161
162func TestAPICall(t *testing.T) {
163	_, c, cleanup := setup()
164	defer cleanup()
165
166	req := &basepb.StringProto{
167		Value: proto.String("Doctor Who"),
168	}
169	res := &basepb.StringProto{}
170	err := Call(toContext(c), "actordb", "LookupActor", req, res)
171	if err != nil {
172		t.Fatalf("API call failed: %v", err)
173	}
174	if got, want := *res.Value, "David Tennant"; got != want {
175		t.Errorf("Response is %q, want %q", got, want)
176	}
177}
178
179func TestAPICallTicketUnavailable(t *testing.T) {
180	resetEnv := SetTestEnv()
181	defer resetEnv()
182	_, c, cleanup := setup()
183	defer cleanup()
184
185	c.req.Header.Set(ticketHeader, "")
186	req := &basepb.StringProto{
187		Value: proto.String("Doctor Who"),
188	}
189	res := &basepb.StringProto{}
190	err := Call(toContext(c), "actordb", "LookupActor", req, res)
191	if err != nil {
192		t.Fatalf("API call failed: %v", err)
193	}
194	if got, want := *res.Value, "David Tennant"; got != want {
195		t.Errorf("Response is %q, want %q", got, want)
196	}
197}
198
199func TestAPICallRPCFailure(t *testing.T) {
200	f, c, cleanup := setup()
201	defer cleanup()
202
203	testCases := []struct {
204		method string
205		code   remotepb.RpcError_ErrorCode
206	}{
207		{"Non200", remotepb.RpcError_UNKNOWN},
208		{"ShortResponse", remotepb.RpcError_UNKNOWN},
209		{"OverQuota", remotepb.RpcError_OVER_QUOTA},
210		{"RunSlowly", remotepb.RpcError_CANCELLED},
211	}
212	f.hang = make(chan int) // only for RunSlowly
213	for _, tc := range testCases {
214		ctx, _ := netcontext.WithTimeout(toContext(c), 100*time.Millisecond)
215		err := Call(ctx, "errors", tc.method, &basepb.VoidProto{}, &basepb.VoidProto{})
216		ce, ok := err.(*CallError)
217		if !ok {
218			t.Errorf("%s: API call error is %T (%v), want *CallError", tc.method, err, err)
219			continue
220		}
221		if ce.Code != int32(tc.code) {
222			t.Errorf("%s: ce.Code = %d, want %d", tc.method, ce.Code, tc.code)
223		}
224		if tc.method == "RunSlowly" {
225			f.hang <- 1 // release the HTTP handler
226		}
227	}
228}
229
230func TestAPICallDialFailure(t *testing.T) {
231	// See what happens if the API host is unresponsive.
232	// This should time out quickly, not hang forever.
233	_, c, cleanup := setup()
234	defer cleanup()
235	// Reset the URL to the production address so that dialing fails.
236	c.apiURL = apiURL()
237
238	start := time.Now()
239	err := Call(toContext(c), "foo", "bar", &basepb.VoidProto{}, &basepb.VoidProto{})
240	const max = 1 * time.Second
241	if taken := time.Since(start); taken > max {
242		t.Errorf("Dial hang took too long: %v > %v", taken, max)
243	}
244	if err == nil {
245		t.Error("Call did not fail")
246	}
247}
248
249func TestDelayedLogFlushing(t *testing.T) {
250	f, c, cleanup := setup()
251	defer cleanup()
252
253	http.HandleFunc("/slow_log", func(w http.ResponseWriter, r *http.Request) {
254		logC := WithContext(netcontext.Background(), r)
255		fromContext(logC).apiURL = c.apiURL // Otherwise it will try to use the default URL.
256		Logf(logC, 1, "It's a lovely day.")
257		w.WriteHeader(200)
258		time.Sleep(1200 * time.Millisecond)
259		w.Write(make([]byte, 100<<10)) // write 100 KB to force HTTP flush
260	})
261
262	r := &http.Request{
263		Method: "GET",
264		URL: &url.URL{
265			Scheme: "http",
266			Path:   "/slow_log",
267		},
268		Header: c.req.Header,
269		Body:   ioutil.NopCloser(bytes.NewReader(nil)),
270	}
271	w := httptest.NewRecorder()
272
273	handled := make(chan struct{})
274	go func() {
275		defer close(handled)
276		handleHTTP(w, r)
277	}()
278	// Check that the log flush eventually comes in.
279	time.Sleep(1200 * time.Millisecond)
280	if f := atomic.LoadInt32(&f.LogFlushes); f != 1 {
281		t.Errorf("After 1.2s: f.LogFlushes = %d, want 1", f)
282	}
283
284	<-handled
285	const hdr = "X-AppEngine-Log-Flush-Count"
286	if got, want := w.HeaderMap.Get(hdr), "1"; got != want {
287		t.Errorf("%s header = %q, want %q", hdr, got, want)
288	}
289	if got, want := atomic.LoadInt32(&f.LogFlushes), int32(2); got != want {
290		t.Errorf("After HTTP response: f.LogFlushes = %d, want %d", got, want)
291	}
292
293}
294
295func TestLogFlushing(t *testing.T) {
296	f, c, cleanup := setup()
297	defer cleanup()
298
299	http.HandleFunc("/quick_log", func(w http.ResponseWriter, r *http.Request) {
300		logC := WithContext(netcontext.Background(), r)
301		fromContext(logC).apiURL = c.apiURL // Otherwise it will try to use the default URL.
302		Logf(logC, 1, "It's a lovely day.")
303		w.WriteHeader(200)
304		w.Write(make([]byte, 100<<10)) // write 100 KB to force HTTP flush
305	})
306
307	r := &http.Request{
308		Method: "GET",
309		URL: &url.URL{
310			Scheme: "http",
311			Path:   "/quick_log",
312		},
313		Header: c.req.Header,
314		Body:   ioutil.NopCloser(bytes.NewReader(nil)),
315	}
316	w := httptest.NewRecorder()
317
318	handleHTTP(w, r)
319	const hdr = "X-AppEngine-Log-Flush-Count"
320	if got, want := w.HeaderMap.Get(hdr), "1"; got != want {
321		t.Errorf("%s header = %q, want %q", hdr, got, want)
322	}
323	if got, want := atomic.LoadInt32(&f.LogFlushes), int32(1); got != want {
324		t.Errorf("After HTTP response: f.LogFlushes = %d, want %d", got, want)
325	}
326}
327
328func TestRemoteAddr(t *testing.T) {
329	var addr string
330	http.HandleFunc("/remote_addr", func(w http.ResponseWriter, r *http.Request) {
331		addr = r.RemoteAddr
332	})
333
334	testCases := []struct {
335		headers http.Header
336		addr    string
337	}{
338		{http.Header{"X-Appengine-User-Ip": []string{"10.5.2.1"}}, "10.5.2.1:80"},
339		{http.Header{"X-Appengine-Remote-Addr": []string{"1.2.3.4"}}, "1.2.3.4:80"},
340		{http.Header{"X-Appengine-Remote-Addr": []string{"1.2.3.4:8080"}}, "1.2.3.4:8080"},
341		{
342			http.Header{"X-Appengine-Remote-Addr": []string{"2401:fa00:9:1:7646:a0ff:fe90:ca66"}},
343			"[2401:fa00:9:1:7646:a0ff:fe90:ca66]:80",
344		},
345		{
346			http.Header{"X-Appengine-Remote-Addr": []string{"[::1]:http"}},
347			"[::1]:http",
348		},
349		{http.Header{}, "127.0.0.1:80"},
350	}
351
352	for _, tc := range testCases {
353		r := &http.Request{
354			Method: "GET",
355			URL:    &url.URL{Scheme: "http", Path: "/remote_addr"},
356			Header: tc.headers,
357			Body:   ioutil.NopCloser(bytes.NewReader(nil)),
358		}
359		handleHTTP(httptest.NewRecorder(), r)
360		if addr != tc.addr {
361			t.Errorf("Header %v, got %q, want %q", tc.headers, addr, tc.addr)
362		}
363	}
364}
365
366func TestPanickingHandler(t *testing.T) {
367	http.HandleFunc("/panic", func(http.ResponseWriter, *http.Request) {
368		panic("whoops!")
369	})
370	r := &http.Request{
371		Method: "GET",
372		URL:    &url.URL{Scheme: "http", Path: "/panic"},
373		Body:   ioutil.NopCloser(bytes.NewReader(nil)),
374	}
375	rec := httptest.NewRecorder()
376	handleHTTP(rec, r)
377	if rec.Code != 500 {
378		t.Errorf("Panicking handler returned HTTP %d, want HTTP %d", rec.Code, 500)
379	}
380}
381
382var raceDetector = false
383
384func TestAPICallAllocations(t *testing.T) {
385	if raceDetector {
386		t.Skip("not running under race detector")
387	}
388
389	// Run the test API server in a subprocess so we aren't counting its allocations.
390	u, cleanup := launchHelperProcess(t)
391	defer cleanup()
392	c := &context{
393		req: &http.Request{
394			Header: http.Header{
395				ticketHeader: []string{"s3cr3t"},
396				dapperHeader: []string{"trace-001"},
397			},
398		},
399		apiURL: u,
400	}
401
402	req := &basepb.StringProto{
403		Value: proto.String("Doctor Who"),
404	}
405	res := &basepb.StringProto{}
406	var apiErr error
407	avg := testing.AllocsPerRun(100, func() {
408		ctx, _ := netcontext.WithTimeout(toContext(c), 100*time.Millisecond)
409		if err := Call(ctx, "actordb", "LookupActor", req, res); err != nil && apiErr == nil {
410			apiErr = err // get the first error only
411		}
412	})
413	if apiErr != nil {
414		t.Errorf("API call failed: %v", apiErr)
415	}
416
417	// Lots of room for improvement...
418	const min, max float64 = 60, 85
419	if avg < min || max < avg {
420		t.Errorf("Allocations per API call = %g, want in [%g,%g]", avg, min, max)
421	}
422}
423
424func launchHelperProcess(t *testing.T) (apiURL *url.URL, cleanup func()) {
425	cmd := exec.Command(os.Args[0], "-test.run=TestHelperProcess")
426	cmd.Env = []string{"GO_WANT_HELPER_PROCESS=1"}
427	stdin, err := cmd.StdinPipe()
428	if err != nil {
429		t.Fatalf("StdinPipe: %v", err)
430	}
431	stdout, err := cmd.StdoutPipe()
432	if err != nil {
433		t.Fatalf("StdoutPipe: %v", err)
434	}
435	if err := cmd.Start(); err != nil {
436		t.Fatalf("Starting helper process: %v", err)
437	}
438
439	scan := bufio.NewScanner(stdout)
440	var u *url.URL
441	for scan.Scan() {
442		line := scan.Text()
443		if hp := strings.TrimPrefix(line, helperProcessMagic); hp != line {
444			var err error
445			u, err = url.Parse(hp)
446			if err != nil {
447				t.Fatalf("Failed to parse %q: %v", hp, err)
448			}
449			break
450		}
451	}
452	if err := scan.Err(); err != nil {
453		t.Fatalf("Scanning helper process stdout: %v", err)
454	}
455	if u == nil {
456		t.Fatal("Helper process never reported")
457	}
458
459	return u, func() {
460		stdin.Close()
461		if err := cmd.Wait(); err != nil {
462			t.Errorf("Helper process did not exit cleanly: %v", err)
463		}
464	}
465}
466
467const helperProcessMagic = "A lovely helper process is listening at "
468
469// This isn't a real test. It's used as a helper process.
470func TestHelperProcess(*testing.T) {
471	if os.Getenv("GO_WANT_HELPER_PROCESS") != "1" {
472		return
473	}
474	defer os.Exit(0)
475
476	f := &fakeAPIHandler{}
477	srv := httptest.NewServer(f)
478	defer srv.Close()
479	fmt.Println(helperProcessMagic + srv.URL + apiPath)
480
481	// Wait for stdin to be closed.
482	io.Copy(ioutil.Discard, os.Stdin)
483}
484
485func TestBackgroundContext(t *testing.T) {
486	resetEnv := SetTestEnv()
487	defer resetEnv()
488
489	ctx, key := fromContext(BackgroundContext()), "X-Magic-Ticket-Header"
490	if g, w := ctx.req.Header.Get(key), "my-app-id/default.20150612t184001.0"; g != w {
491		t.Errorf("%v = %q, want %q", key, g, w)
492	}
493
494	// Check that using the background context doesn't panic.
495	req := &basepb.StringProto{
496		Value: proto.String("Doctor Who"),
497	}
498	res := &basepb.StringProto{}
499	Call(BackgroundContext(), "actordb", "LookupActor", req, res) // expected to fail
500}
501