github.com/mongey/nomad@v0.5.2/command/agent/fs_endpoint_test.go (about) 1 package agent 2 3 import ( 4 "bytes" 5 "fmt" 6 "io" 7 "io/ioutil" 8 "math" 9 "net/http" 10 "net/http/httptest" 11 "os" 12 "path/filepath" 13 "reflect" 14 "runtime" 15 "strconv" 16 "testing" 17 "time" 18 19 "github.com/hashicorp/nomad/client/allocdir" 20 "github.com/hashicorp/nomad/testutil" 21 "github.com/ugorji/go/codec" 22 ) 23 24 func TestAllocDirFS_List_MissingParams(t *testing.T) { 25 httpTest(t, nil, func(s *TestServer) { 26 req, err := http.NewRequest("GET", "/v1/client/fs/ls/", nil) 27 if err != nil { 28 t.Fatalf("err: %v", err) 29 } 30 respW := httptest.NewRecorder() 31 32 _, err = s.Server.DirectoryListRequest(respW, req) 33 if err != allocIDNotPresentErr { 34 t.Fatalf("expected err: %v, actual: %v", allocIDNotPresentErr, err) 35 } 36 }) 37 } 38 39 func TestAllocDirFS_Stat_MissingParams(t *testing.T) { 40 httpTest(t, nil, func(s *TestServer) { 41 req, err := http.NewRequest("GET", "/v1/client/fs/stat/", nil) 42 if err != nil { 43 t.Fatalf("err: %v", err) 44 } 45 respW := httptest.NewRecorder() 46 47 _, err = s.Server.FileStatRequest(respW, req) 48 if err != allocIDNotPresentErr { 49 t.Fatalf("expected err: %v, actual: %v", allocIDNotPresentErr, err) 50 } 51 52 req, err = http.NewRequest("GET", "/v1/client/fs/stat/foo", nil) 53 if err != nil { 54 t.Fatalf("err: %v", err) 55 } 56 respW = httptest.NewRecorder() 57 58 _, err = s.Server.FileStatRequest(respW, req) 59 if err != fileNameNotPresentErr { 60 t.Fatalf("expected err: %v, actual: %v", allocIDNotPresentErr, err) 61 } 62 63 }) 64 } 65 66 func TestAllocDirFS_ReadAt_MissingParams(t *testing.T) { 67 httpTest(t, nil, func(s *TestServer) { 68 req, err := http.NewRequest("GET", "/v1/client/fs/readat/", nil) 69 if err != nil { 70 t.Fatalf("err: %v", err) 71 } 72 respW := httptest.NewRecorder() 73 74 _, err = s.Server.FileReadAtRequest(respW, req) 75 if err == nil { 76 t.Fatal("expected error") 77 } 78 79 req, err = http.NewRequest("GET", "/v1/client/fs/readat/foo", nil) 80 if err != nil { 81 t.Fatalf("err: %v", err) 82 } 83 respW = httptest.NewRecorder() 84 85 _, err = s.Server.FileReadAtRequest(respW, req) 86 if err == nil { 87 t.Fatal("expected error") 88 } 89 90 req, err = http.NewRequest("GET", "/v1/client/fs/readat/foo?path=/path/to/file", nil) 91 if err != nil { 92 t.Fatalf("err: %v", err) 93 } 94 respW = httptest.NewRecorder() 95 96 _, err = s.Server.FileReadAtRequest(respW, req) 97 if err == nil { 98 t.Fatal("expected error") 99 } 100 }) 101 } 102 103 type WriteCloseChecker struct { 104 io.WriteCloser 105 Closed bool 106 } 107 108 func (w *WriteCloseChecker) Close() error { 109 w.Closed = true 110 return w.WriteCloser.Close() 111 } 112 113 // This test checks, that even if the frame size has not been hit, a flush will 114 // periodically occur. 115 func TestStreamFramer_Flush(t *testing.T) { 116 // Create the stream framer 117 r, w := io.Pipe() 118 wrappedW := &WriteCloseChecker{WriteCloser: w} 119 hRate, bWindow := 100*time.Millisecond, 100*time.Millisecond 120 sf := NewStreamFramer(wrappedW, hRate, bWindow, 100) 121 sf.Run() 122 123 // Create a decoder 124 dec := codec.NewDecoder(r, jsonHandle) 125 126 f := "foo" 127 fe := "bar" 128 d := []byte{0xa} 129 o := int64(10) 130 131 // Start the reader 132 resultCh := make(chan struct{}) 133 go func() { 134 for { 135 var frame StreamFrame 136 if err := dec.Decode(&frame); err != nil { 137 t.Fatalf("failed to decode") 138 } 139 140 if frame.IsHeartbeat() { 141 continue 142 } 143 144 if reflect.DeepEqual(frame.Data, d) && frame.Offset == o && frame.File == f && frame.FileEvent == fe { 145 resultCh <- struct{}{} 146 return 147 } 148 149 } 150 }() 151 152 // Write only 1 byte so we do not hit the frame size 153 if err := sf.Send(f, fe, d, o); err != nil { 154 t.Fatalf("Send() failed %v", err) 155 } 156 157 select { 158 case <-resultCh: 159 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * bWindow): 160 t.Fatalf("failed to flush") 161 } 162 163 // Close the reader and wait. This should cause the runner to exit 164 if err := r.Close(); err != nil { 165 t.Fatalf("failed to close reader") 166 } 167 168 select { 169 case <-sf.ExitCh(): 170 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * hRate): 171 t.Fatalf("exit channel should close") 172 } 173 174 sf.Destroy() 175 if !wrappedW.Closed { 176 t.Fatalf("writer not closed") 177 } 178 } 179 180 // This test checks that frames will be batched till the frame size is hit (in 181 // the case that is before the flush). 182 func TestStreamFramer_Batch(t *testing.T) { 183 // Create the stream framer 184 r, w := io.Pipe() 185 wrappedW := &WriteCloseChecker{WriteCloser: w} 186 // Ensure the batch window doesn't get hit 187 hRate, bWindow := 100*time.Millisecond, 500*time.Millisecond 188 sf := NewStreamFramer(wrappedW, hRate, bWindow, 3) 189 sf.Run() 190 191 // Create a decoder 192 dec := codec.NewDecoder(r, jsonHandle) 193 194 f := "foo" 195 fe := "bar" 196 d := []byte{0xa, 0xb, 0xc} 197 o := int64(10) 198 199 // Start the reader 200 resultCh := make(chan struct{}) 201 go func() { 202 for { 203 var frame StreamFrame 204 if err := dec.Decode(&frame); err != nil { 205 t.Fatalf("failed to decode") 206 } 207 208 if frame.IsHeartbeat() { 209 continue 210 } 211 212 if reflect.DeepEqual(frame.Data, d) && frame.Offset == o && frame.File == f && frame.FileEvent == fe { 213 resultCh <- struct{}{} 214 return 215 } 216 } 217 }() 218 219 // Write only 1 byte so we do not hit the frame size 220 if err := sf.Send(f, fe, d[:1], o); err != nil { 221 t.Fatalf("Send() failed %v", err) 222 } 223 224 // Ensure we didn't get any data 225 select { 226 case <-resultCh: 227 t.Fatalf("Got data before frame size reached") 228 case <-time.After(bWindow / 2): 229 } 230 231 // Write the rest so we hit the frame size 232 if err := sf.Send(f, fe, d[1:], o); err != nil { 233 t.Fatalf("Send() failed %v", err) 234 } 235 236 // Ensure we get data 237 select { 238 case <-resultCh: 239 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * bWindow): 240 t.Fatalf("Did not receive data after batch size reached") 241 } 242 243 // Close the reader and wait. This should cause the runner to exit 244 if err := r.Close(); err != nil { 245 t.Fatalf("failed to close reader") 246 } 247 248 select { 249 case <-sf.ExitCh(): 250 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * hRate): 251 t.Fatalf("exit channel should close") 252 } 253 254 sf.Destroy() 255 if !wrappedW.Closed { 256 t.Fatalf("writer not closed") 257 } 258 } 259 260 func TestStreamFramer_Heartbeat(t *testing.T) { 261 // Create the stream framer 262 r, w := io.Pipe() 263 wrappedW := &WriteCloseChecker{WriteCloser: w} 264 hRate, bWindow := 100*time.Millisecond, 100*time.Millisecond 265 sf := NewStreamFramer(wrappedW, hRate, bWindow, 100) 266 sf.Run() 267 268 // Create a decoder 269 dec := codec.NewDecoder(r, jsonHandle) 270 271 // Start the reader 272 resultCh := make(chan struct{}) 273 go func() { 274 for { 275 var frame StreamFrame 276 if err := dec.Decode(&frame); err != nil { 277 t.Fatalf("failed to decode") 278 } 279 280 if frame.IsHeartbeat() { 281 resultCh <- struct{}{} 282 return 283 } 284 } 285 }() 286 287 select { 288 case <-resultCh: 289 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * hRate): 290 t.Fatalf("failed to heartbeat") 291 } 292 293 // Close the reader and wait. This should cause the runner to exit 294 if err := r.Close(); err != nil { 295 t.Fatalf("failed to close reader") 296 } 297 298 select { 299 case <-sf.ExitCh(): 300 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * hRate): 301 t.Fatalf("exit channel should close") 302 } 303 304 sf.Destroy() 305 if !wrappedW.Closed { 306 t.Fatalf("writer not closed") 307 } 308 } 309 310 // This test checks that frames are received in order 311 func TestStreamFramer_Order(t *testing.T) { 312 // Create the stream framer 313 r, w := io.Pipe() 314 wrappedW := &WriteCloseChecker{WriteCloser: w} 315 // Ensure the batch window doesn't get hit 316 hRate, bWindow := 100*time.Millisecond, 10*time.Millisecond 317 sf := NewStreamFramer(wrappedW, hRate, bWindow, 10) 318 sf.Run() 319 320 // Create a decoder 321 dec := codec.NewDecoder(r, jsonHandle) 322 323 files := []string{"1", "2", "3", "4", "5"} 324 input := bytes.NewBuffer(make([]byte, 0, 100000)) 325 for i := 0; i <= 1000; i++ { 326 str := strconv.Itoa(i) + "," 327 input.WriteString(str) 328 } 329 330 expected := bytes.NewBuffer(make([]byte, 0, 100000)) 331 for _, _ = range files { 332 expected.Write(input.Bytes()) 333 } 334 receivedBuf := bytes.NewBuffer(make([]byte, 0, 100000)) 335 336 // Start the reader 337 resultCh := make(chan struct{}) 338 go func() { 339 for { 340 var frame StreamFrame 341 if err := dec.Decode(&frame); err != nil { 342 t.Fatalf("failed to decode") 343 } 344 345 if frame.IsHeartbeat() { 346 continue 347 } 348 349 receivedBuf.Write(frame.Data) 350 351 if reflect.DeepEqual(expected, receivedBuf) { 352 resultCh <- struct{}{} 353 return 354 } 355 } 356 }() 357 358 // Send the data 359 b := input.Bytes() 360 shards := 10 361 each := len(b) / shards 362 for _, f := range files { 363 for i := 0; i < shards; i++ { 364 l, r := each*i, each*(i+1) 365 if i == shards-1 { 366 r = len(b) 367 } 368 369 if err := sf.Send(f, "", b[l:r], 0); err != nil { 370 t.Fatalf("Send() failed %v", err) 371 } 372 } 373 } 374 375 // Ensure we get data 376 select { 377 case <-resultCh: 378 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * bWindow): 379 if reflect.DeepEqual(expected, receivedBuf) { 380 got := receivedBuf.String() 381 want := expected.String() 382 t.Fatalf("Got %v; want %v", got, want) 383 } 384 } 385 386 // Close the reader and wait. This should cause the runner to exit 387 if err := r.Close(); err != nil { 388 t.Fatalf("failed to close reader") 389 } 390 391 select { 392 case <-sf.ExitCh(): 393 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * hRate): 394 t.Fatalf("exit channel should close") 395 } 396 397 sf.Destroy() 398 if !wrappedW.Closed { 399 t.Fatalf("writer not closed") 400 } 401 } 402 403 func TestHTTP_Stream_MissingParams(t *testing.T) { 404 httpTest(t, nil, func(s *TestServer) { 405 req, err := http.NewRequest("GET", "/v1/client/fs/stream/", nil) 406 if err != nil { 407 t.Fatalf("err: %v", err) 408 } 409 respW := httptest.NewRecorder() 410 411 _, err = s.Server.Stream(respW, req) 412 if err == nil { 413 t.Fatal("expected error") 414 } 415 416 req, err = http.NewRequest("GET", "/v1/client/fs/stream/foo", nil) 417 if err != nil { 418 t.Fatalf("err: %v", err) 419 } 420 respW = httptest.NewRecorder() 421 422 _, err = s.Server.Stream(respW, req) 423 if err == nil { 424 t.Fatal("expected error") 425 } 426 427 req, err = http.NewRequest("GET", "/v1/client/fs/stream/foo?path=/path/to/file", nil) 428 if err != nil { 429 t.Fatalf("err: %v", err) 430 } 431 respW = httptest.NewRecorder() 432 433 _, err = s.Server.Stream(respW, req) 434 if err == nil { 435 t.Fatal("expected error") 436 } 437 }) 438 } 439 440 // tempAllocDir returns a new alloc dir that is rooted in a temp dir. The caller 441 // should destroy the temp dir. 442 func tempAllocDir(t testing.TB) *allocdir.AllocDir { 443 dir, err := ioutil.TempDir("", "") 444 if err != nil { 445 t.Fatalf("TempDir() failed: %v", err) 446 } 447 448 if err := os.Chmod(dir, 0777); err != nil { 449 t.Fatalf("failed to chmod dir: %v", err) 450 } 451 452 return allocdir.NewAllocDir(dir) 453 } 454 455 type nopWriteCloser struct { 456 io.Writer 457 } 458 459 func (n nopWriteCloser) Close() error { 460 return nil 461 } 462 463 func TestHTTP_Stream_NoFile(t *testing.T) { 464 httpTest(t, nil, func(s *TestServer) { 465 // Get a temp alloc dir 466 ad := tempAllocDir(t) 467 defer os.RemoveAll(ad.AllocDir) 468 469 framer := NewStreamFramer(nopWriteCloser{ioutil.Discard}, streamHeartbeatRate, streamBatchWindow, streamFrameSize) 470 framer.Run() 471 defer framer.Destroy() 472 473 if err := s.Server.stream(0, "foo", ad, framer, nil); err == nil { 474 t.Fatalf("expected an error when streaming unknown file") 475 } 476 }) 477 } 478 479 func TestHTTP_Stream_Modify(t *testing.T) { 480 httpTest(t, nil, func(s *TestServer) { 481 // Get a temp alloc dir 482 ad := tempAllocDir(t) 483 defer os.RemoveAll(ad.AllocDir) 484 485 // Create a file in the temp dir 486 streamFile := "stream_file" 487 f, err := os.Create(filepath.Join(ad.AllocDir, streamFile)) 488 if err != nil { 489 t.Fatalf("Failed to create file: %v", err) 490 } 491 defer f.Close() 492 493 // Create a decoder 494 r, w := io.Pipe() 495 defer r.Close() 496 defer w.Close() 497 dec := codec.NewDecoder(r, jsonHandle) 498 499 data := []byte("helloworld") 500 501 // Start the reader 502 resultCh := make(chan struct{}) 503 go func() { 504 var collected []byte 505 for { 506 var frame StreamFrame 507 if err := dec.Decode(&frame); err != nil { 508 t.Fatalf("failed to decode: %v", err) 509 } 510 511 if frame.IsHeartbeat() { 512 continue 513 } 514 515 collected = append(collected, frame.Data...) 516 if reflect.DeepEqual(data, collected) { 517 resultCh <- struct{}{} 518 return 519 } 520 } 521 }() 522 523 // Write a few bytes 524 if _, err := f.Write(data[:3]); err != nil { 525 t.Fatalf("write failed: %v", err) 526 } 527 528 framer := NewStreamFramer(w, streamHeartbeatRate, streamBatchWindow, streamFrameSize) 529 framer.Run() 530 defer framer.Destroy() 531 532 // Start streaming 533 go func() { 534 if err := s.Server.stream(0, streamFile, ad, framer, nil); err != nil { 535 t.Fatalf("stream() failed: %v", err) 536 } 537 }() 538 539 // Sleep a little before writing more. This lets us check if the watch 540 // is working. 541 time.Sleep(1 * time.Duration(testutil.TestMultiplier()) * time.Second) 542 if _, err := f.Write(data[3:]); err != nil { 543 t.Fatalf("write failed: %v", err) 544 } 545 546 select { 547 case <-resultCh: 548 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * streamBatchWindow): 549 t.Fatalf("failed to send new data") 550 } 551 }) 552 } 553 554 func TestHTTP_Stream_Truncate(t *testing.T) { 555 httpTest(t, nil, func(s *TestServer) { 556 // Get a temp alloc dir 557 ad := tempAllocDir(t) 558 defer os.RemoveAll(ad.AllocDir) 559 560 // Create a file in the temp dir 561 streamFile := "stream_file" 562 streamFilePath := filepath.Join(ad.AllocDir, streamFile) 563 f, err := os.Create(streamFilePath) 564 if err != nil { 565 t.Fatalf("Failed to create file: %v", err) 566 } 567 defer f.Close() 568 569 // Create a decoder 570 r, w := io.Pipe() 571 defer r.Close() 572 defer w.Close() 573 dec := codec.NewDecoder(r, jsonHandle) 574 575 data := []byte("helloworld") 576 577 // Start the reader 578 truncateCh := make(chan struct{}) 579 dataPostTruncCh := make(chan struct{}) 580 go func() { 581 var collected []byte 582 for { 583 var frame StreamFrame 584 if err := dec.Decode(&frame); err != nil { 585 t.Fatalf("failed to decode: %v", err) 586 } 587 588 if frame.IsHeartbeat() { 589 continue 590 } 591 592 if frame.FileEvent == truncateEvent { 593 close(truncateCh) 594 } 595 596 collected = append(collected, frame.Data...) 597 if reflect.DeepEqual(data, collected) { 598 close(dataPostTruncCh) 599 return 600 } 601 } 602 }() 603 604 // Write a few bytes 605 if _, err := f.Write(data[:3]); err != nil { 606 t.Fatalf("write failed: %v", err) 607 } 608 609 framer := NewStreamFramer(w, streamHeartbeatRate, streamBatchWindow, streamFrameSize) 610 framer.Run() 611 defer framer.Destroy() 612 613 // Start streaming 614 go func() { 615 if err := s.Server.stream(0, streamFile, ad, framer, nil); err != nil { 616 t.Fatalf("stream() failed: %v", err) 617 } 618 }() 619 620 // Sleep a little before truncating. This lets us check if the watch 621 // is working. 622 time.Sleep(1 * time.Duration(testutil.TestMultiplier()) * time.Second) 623 if err := f.Truncate(0); err != nil { 624 t.Fatalf("truncate failed: %v", err) 625 } 626 if err := f.Sync(); err != nil { 627 t.Fatalf("sync failed: %v", err) 628 } 629 if err := f.Close(); err != nil { 630 t.Fatalf("failed to close file: %v", err) 631 } 632 633 f2, err := os.OpenFile(streamFilePath, os.O_RDWR, 0) 634 if err != nil { 635 t.Fatalf("failed to reopen file: %v", err) 636 } 637 defer f2.Close() 638 if _, err := f2.Write(data[3:5]); err != nil { 639 t.Fatalf("write failed: %v", err) 640 } 641 642 select { 643 case <-truncateCh: 644 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * streamBatchWindow): 645 t.Fatalf("did not receive truncate") 646 } 647 648 // Sleep a little before writing more. This lets us check if the watch 649 // is working. 650 time.Sleep(1 * time.Duration(testutil.TestMultiplier()) * time.Second) 651 if _, err := f2.Write(data[5:]); err != nil { 652 t.Fatalf("write failed: %v", err) 653 } 654 655 select { 656 case <-dataPostTruncCh: 657 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * streamBatchWindow): 658 t.Fatalf("did not receive post truncate data") 659 } 660 }) 661 } 662 663 func TestHTTP_Stream_Delete(t *testing.T) { 664 httpTest(t, nil, func(s *TestServer) { 665 // Get a temp alloc dir 666 ad := tempAllocDir(t) 667 defer os.RemoveAll(ad.AllocDir) 668 669 // Create a file in the temp dir 670 streamFile := "stream_file" 671 streamFilePath := filepath.Join(ad.AllocDir, streamFile) 672 f, err := os.Create(streamFilePath) 673 if err != nil { 674 t.Fatalf("Failed to create file: %v", err) 675 } 676 defer f.Close() 677 678 // Create a decoder 679 r, w := io.Pipe() 680 wrappedW := &WriteCloseChecker{WriteCloser: w} 681 defer r.Close() 682 defer w.Close() 683 dec := codec.NewDecoder(r, jsonHandle) 684 685 data := []byte("helloworld") 686 687 // Start the reader 688 deleteCh := make(chan struct{}) 689 go func() { 690 for { 691 var frame StreamFrame 692 if err := dec.Decode(&frame); err != nil { 693 t.Fatalf("failed to decode: %v", err) 694 } 695 696 if frame.IsHeartbeat() { 697 continue 698 } 699 700 if frame.FileEvent == deleteEvent { 701 close(deleteCh) 702 return 703 } 704 } 705 }() 706 707 // Write a few bytes 708 if _, err := f.Write(data[:3]); err != nil { 709 t.Fatalf("write failed: %v", err) 710 } 711 712 framer := NewStreamFramer(wrappedW, streamHeartbeatRate, streamBatchWindow, streamFrameSize) 713 framer.Run() 714 715 // Start streaming 716 go func() { 717 if err := s.Server.stream(0, streamFile, ad, framer, nil); err != nil { 718 t.Fatalf("stream() failed: %v", err) 719 } 720 }() 721 722 // Sleep a little before deleting. This lets us check if the watch 723 // is working. 724 time.Sleep(1 * time.Duration(testutil.TestMultiplier()) * time.Second) 725 if err := os.Remove(streamFilePath); err != nil { 726 t.Fatalf("delete failed: %v", err) 727 } 728 729 select { 730 case <-deleteCh: 731 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * streamBatchWindow): 732 t.Fatalf("did not receive delete") 733 } 734 735 framer.Destroy() 736 testutil.WaitForResult(func() (bool, error) { 737 return wrappedW.Closed, nil 738 }, func(err error) { 739 t.Fatalf("connection not closed") 740 }) 741 742 }) 743 } 744 745 func TestHTTP_Logs_NoFollow(t *testing.T) { 746 httpTest(t, nil, func(s *TestServer) { 747 // Get a temp alloc dir and create the log dir 748 ad := tempAllocDir(t) 749 defer os.RemoveAll(ad.AllocDir) 750 751 logDir := filepath.Join(ad.SharedDir, allocdir.LogDirName) 752 if err := os.MkdirAll(logDir, 0777); err != nil { 753 t.Fatalf("Failed to make log dir: %v", err) 754 } 755 756 // Create a series of log files in the temp dir 757 task := "foo" 758 logType := "stdout" 759 expected := []byte("012") 760 for i := 0; i < 3; i++ { 761 logFile := fmt.Sprintf("%s.%s.%d", task, logType, i) 762 logFilePath := filepath.Join(logDir, logFile) 763 err := ioutil.WriteFile(logFilePath, expected[i:i+1], 777) 764 if err != nil { 765 t.Fatalf("Failed to create file: %v", err) 766 } 767 } 768 769 // Create a decoder 770 r, w := io.Pipe() 771 wrappedW := &WriteCloseChecker{WriteCloser: w} 772 defer r.Close() 773 defer w.Close() 774 dec := codec.NewDecoder(r, jsonHandle) 775 776 var received []byte 777 778 // Start the reader 779 resultCh := make(chan struct{}) 780 go func() { 781 for { 782 var frame StreamFrame 783 if err := dec.Decode(&frame); err != nil { 784 if err == io.EOF { 785 t.Logf("EOF") 786 return 787 } 788 789 t.Fatalf("failed to decode: %v", err) 790 } 791 792 if frame.IsHeartbeat() { 793 continue 794 } 795 796 received = append(received, frame.Data...) 797 if reflect.DeepEqual(received, expected) { 798 close(resultCh) 799 return 800 } 801 } 802 }() 803 804 // Start streaming logs 805 go func() { 806 if err := s.Server.logs(false, 0, OriginStart, task, logType, ad, wrappedW); err != nil { 807 t.Fatalf("logs() failed: %v", err) 808 } 809 }() 810 811 select { 812 case <-resultCh: 813 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * streamBatchWindow): 814 t.Fatalf("did not receive data: got %q", string(received)) 815 } 816 817 testutil.WaitForResult(func() (bool, error) { 818 return wrappedW.Closed, nil 819 }, func(err error) { 820 t.Fatalf("connection not closed") 821 }) 822 823 }) 824 } 825 826 func TestHTTP_Logs_Follow(t *testing.T) { 827 httpTest(t, nil, func(s *TestServer) { 828 // Get a temp alloc dir and create the log dir 829 ad := tempAllocDir(t) 830 defer os.RemoveAll(ad.AllocDir) 831 832 logDir := filepath.Join(ad.SharedDir, allocdir.LogDirName) 833 if err := os.MkdirAll(logDir, 0777); err != nil { 834 t.Fatalf("Failed to make log dir: %v", err) 835 } 836 837 // Create a series of log files in the temp dir 838 task := "foo" 839 logType := "stdout" 840 expected := []byte("012345") 841 initialWrites := 3 842 843 writeToFile := func(index int, data []byte) { 844 logFile := fmt.Sprintf("%s.%s.%d", task, logType, index) 845 logFilePath := filepath.Join(logDir, logFile) 846 err := ioutil.WriteFile(logFilePath, data, 777) 847 if err != nil { 848 t.Fatalf("Failed to create file: %v", err) 849 } 850 } 851 for i := 0; i < initialWrites; i++ { 852 writeToFile(i, expected[i:i+1]) 853 } 854 855 // Create a decoder 856 r, w := io.Pipe() 857 wrappedW := &WriteCloseChecker{WriteCloser: w} 858 defer r.Close() 859 defer w.Close() 860 dec := codec.NewDecoder(r, jsonHandle) 861 862 var received []byte 863 864 // Start the reader 865 firstResultCh := make(chan struct{}) 866 fullResultCh := make(chan struct{}) 867 go func() { 868 for { 869 var frame StreamFrame 870 if err := dec.Decode(&frame); err != nil { 871 if err == io.EOF { 872 t.Logf("EOF") 873 return 874 } 875 876 t.Fatalf("failed to decode: %v", err) 877 } 878 879 if frame.IsHeartbeat() { 880 continue 881 } 882 883 received = append(received, frame.Data...) 884 if reflect.DeepEqual(received, expected[:initialWrites]) { 885 close(firstResultCh) 886 } else if reflect.DeepEqual(received, expected) { 887 close(fullResultCh) 888 return 889 } 890 } 891 }() 892 893 // Start streaming logs 894 go func() { 895 if err := s.Server.logs(true, 0, OriginStart, task, logType, ad, wrappedW); err != nil { 896 t.Fatalf("logs() failed: %v", err) 897 } 898 }() 899 900 select { 901 case <-firstResultCh: 902 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * streamBatchWindow): 903 t.Fatalf("did not receive data: got %q", string(received)) 904 } 905 906 // We got the first chunk of data, write out the rest to the next file 907 // at an index much ahead to check that it is following and detecting 908 // skips 909 skipTo := initialWrites + 10 910 writeToFile(skipTo, expected[initialWrites:]) 911 912 select { 913 case <-fullResultCh: 914 case <-time.After(10 * time.Duration(testutil.TestMultiplier()) * streamBatchWindow): 915 t.Fatalf("did not receive data: got %q", string(received)) 916 } 917 918 // Close the reader 919 r.Close() 920 921 testutil.WaitForResult(func() (bool, error) { 922 return wrappedW.Closed, nil 923 }, func(err error) { 924 t.Fatalf("connection not closed") 925 }) 926 }) 927 } 928 929 func BenchmarkHTTP_Logs_Follow(t *testing.B) { 930 runtime.MemProfileRate = 1 931 932 s := makeHTTPServer(t, nil) 933 defer s.Cleanup() 934 testutil.WaitForLeader(t, s.Agent.RPC) 935 936 // Get a temp alloc dir and create the log dir 937 ad := tempAllocDir(t) 938 s.Agent.logger.Printf("ALEX: LOG DIR: %q", ad.SharedDir) 939 //defer os.RemoveAll(ad.AllocDir) 940 941 logDir := filepath.Join(ad.SharedDir, allocdir.LogDirName) 942 if err := os.MkdirAll(logDir, 0777); err != nil { 943 t.Fatalf("Failed to make log dir: %v", err) 944 } 945 946 // Create a series of log files in the temp dir 947 task := "foo" 948 logType := "stdout" 949 expected := make([]byte, 1024*1024*100) 950 initialWrites := 3 951 952 writeToFile := func(index int, data []byte) { 953 logFile := fmt.Sprintf("%s.%s.%d", task, logType, index) 954 logFilePath := filepath.Join(logDir, logFile) 955 err := ioutil.WriteFile(logFilePath, data, 777) 956 if err != nil { 957 t.Fatalf("Failed to create file: %v", err) 958 } 959 } 960 961 part := (len(expected) / 3) - 50 962 goodEnough := (8 * len(expected)) / 10 963 for i := 0; i < initialWrites; i++ { 964 writeToFile(i, expected[i*part:(i+1)*part]) 965 } 966 967 t.ResetTimer() 968 for i := 0; i < t.N; i++ { 969 s.Agent.logger.Printf("BENCHMARK %d", i) 970 971 // Create a decoder 972 r, w := io.Pipe() 973 wrappedW := &WriteCloseChecker{WriteCloser: w} 974 defer r.Close() 975 defer w.Close() 976 dec := codec.NewDecoder(r, jsonHandle) 977 978 var received []byte 979 980 // Start the reader 981 fullResultCh := make(chan struct{}) 982 go func() { 983 for { 984 var frame StreamFrame 985 if err := dec.Decode(&frame); err != nil { 986 if err == io.EOF { 987 t.Logf("EOF") 988 return 989 } 990 991 t.Fatalf("failed to decode: %v", err) 992 } 993 994 if frame.IsHeartbeat() { 995 continue 996 } 997 998 received = append(received, frame.Data...) 999 if len(received) > goodEnough { 1000 close(fullResultCh) 1001 return 1002 } 1003 } 1004 }() 1005 1006 // Start streaming logs 1007 go func() { 1008 if err := s.Server.logs(true, 0, OriginStart, task, logType, ad, wrappedW); err != nil { 1009 t.Fatalf("logs() failed: %v", err) 1010 } 1011 }() 1012 1013 select { 1014 case <-fullResultCh: 1015 case <-time.After(time.Duration(60 * time.Second)): 1016 t.Fatalf("did not receive data: %d < %d", len(received), goodEnough) 1017 } 1018 1019 s.Agent.logger.Printf("ALEX: CLOSING") 1020 1021 // Close the reader 1022 r.Close() 1023 s.Agent.logger.Printf("ALEX: CLOSED") 1024 1025 s.Agent.logger.Printf("ALEX: WAITING FOR WRITER TO CLOSE") 1026 testutil.WaitForResult(func() (bool, error) { 1027 return wrappedW.Closed, nil 1028 }, func(err error) { 1029 t.Fatalf("connection not closed") 1030 }) 1031 s.Agent.logger.Printf("ALEX: WRITER CLOSED") 1032 } 1033 } 1034 1035 func TestLogs_findClosest(t *testing.T) { 1036 task := "foo" 1037 entries := []*allocdir.AllocFileInfo{ 1038 { 1039 Name: "foo.stdout.0", 1040 Size: 100, 1041 }, 1042 { 1043 Name: "foo.stdout.1", 1044 Size: 100, 1045 }, 1046 { 1047 Name: "foo.stdout.2", 1048 Size: 100, 1049 }, 1050 { 1051 Name: "foo.stdout.3", 1052 Size: 100, 1053 }, 1054 { 1055 Name: "foo.stderr.0", 1056 Size: 100, 1057 }, 1058 { 1059 Name: "foo.stderr.1", 1060 Size: 100, 1061 }, 1062 { 1063 Name: "foo.stderr.2", 1064 Size: 100, 1065 }, 1066 } 1067 1068 cases := []struct { 1069 Entries []*allocdir.AllocFileInfo 1070 DesiredIdx int64 1071 DesiredOffset int64 1072 Task string 1073 LogType string 1074 ExpectedFile string 1075 ExpectedIdx int64 1076 ExpectedOffset int64 1077 Error bool 1078 }{ 1079 // Test error cases 1080 { 1081 Entries: nil, 1082 DesiredIdx: 0, 1083 Task: task, 1084 LogType: "stdout", 1085 Error: true, 1086 }, 1087 { 1088 Entries: entries[0:3], 1089 DesiredIdx: 0, 1090 Task: task, 1091 LogType: "stderr", 1092 Error: true, 1093 }, 1094 1095 // Test begining cases 1096 { 1097 Entries: entries, 1098 DesiredIdx: 0, 1099 Task: task, 1100 LogType: "stdout", 1101 ExpectedFile: entries[0].Name, 1102 ExpectedIdx: 0, 1103 }, 1104 { 1105 // Desired offset should be ignored at edges 1106 Entries: entries, 1107 DesiredIdx: 0, 1108 DesiredOffset: -100, 1109 Task: task, 1110 LogType: "stdout", 1111 ExpectedFile: entries[0].Name, 1112 ExpectedIdx: 0, 1113 ExpectedOffset: 0, 1114 }, 1115 { 1116 // Desired offset should be ignored at edges 1117 Entries: entries, 1118 DesiredIdx: 1, 1119 DesiredOffset: -1000, 1120 Task: task, 1121 LogType: "stdout", 1122 ExpectedFile: entries[0].Name, 1123 ExpectedIdx: 0, 1124 ExpectedOffset: 0, 1125 }, 1126 { 1127 Entries: entries, 1128 DesiredIdx: 0, 1129 Task: task, 1130 LogType: "stderr", 1131 ExpectedFile: entries[4].Name, 1132 ExpectedIdx: 0, 1133 }, 1134 { 1135 Entries: entries, 1136 DesiredIdx: 0, 1137 Task: task, 1138 LogType: "stdout", 1139 ExpectedFile: entries[0].Name, 1140 ExpectedIdx: 0, 1141 }, 1142 1143 // Test middle cases 1144 { 1145 Entries: entries, 1146 DesiredIdx: 1, 1147 Task: task, 1148 LogType: "stdout", 1149 ExpectedFile: entries[1].Name, 1150 ExpectedIdx: 1, 1151 }, 1152 { 1153 Entries: entries, 1154 DesiredIdx: 1, 1155 DesiredOffset: 10, 1156 Task: task, 1157 LogType: "stdout", 1158 ExpectedFile: entries[1].Name, 1159 ExpectedIdx: 1, 1160 ExpectedOffset: 10, 1161 }, 1162 { 1163 Entries: entries, 1164 DesiredIdx: 1, 1165 DesiredOffset: 110, 1166 Task: task, 1167 LogType: "stdout", 1168 ExpectedFile: entries[2].Name, 1169 ExpectedIdx: 2, 1170 ExpectedOffset: 10, 1171 }, 1172 { 1173 Entries: entries, 1174 DesiredIdx: 1, 1175 Task: task, 1176 LogType: "stderr", 1177 ExpectedFile: entries[5].Name, 1178 ExpectedIdx: 1, 1179 }, 1180 // Test end cases 1181 { 1182 Entries: entries, 1183 DesiredIdx: math.MaxInt64, 1184 Task: task, 1185 LogType: "stdout", 1186 ExpectedFile: entries[3].Name, 1187 ExpectedIdx: 3, 1188 }, 1189 { 1190 Entries: entries, 1191 DesiredIdx: math.MaxInt64, 1192 DesiredOffset: math.MaxInt64, 1193 Task: task, 1194 LogType: "stdout", 1195 ExpectedFile: entries[3].Name, 1196 ExpectedIdx: 3, 1197 ExpectedOffset: 100, 1198 }, 1199 { 1200 Entries: entries, 1201 DesiredIdx: math.MaxInt64, 1202 DesiredOffset: -10, 1203 Task: task, 1204 LogType: "stdout", 1205 ExpectedFile: entries[3].Name, 1206 ExpectedIdx: 3, 1207 ExpectedOffset: 90, 1208 }, 1209 { 1210 Entries: entries, 1211 DesiredIdx: math.MaxInt64, 1212 Task: task, 1213 LogType: "stderr", 1214 ExpectedFile: entries[6].Name, 1215 ExpectedIdx: 2, 1216 }, 1217 } 1218 1219 for i, c := range cases { 1220 entry, idx, offset, err := findClosest(c.Entries, c.DesiredIdx, c.DesiredOffset, c.Task, c.LogType) 1221 if err != nil { 1222 if !c.Error { 1223 t.Fatalf("case %d: Unexpected error: %v", i, err) 1224 } 1225 continue 1226 } 1227 1228 if entry.Name != c.ExpectedFile { 1229 t.Fatalf("case %d: Got file %q; want %q", i, entry.Name, c.ExpectedFile) 1230 } 1231 if idx != c.ExpectedIdx { 1232 t.Fatalf("case %d: Got index %d; want %d", i, idx, c.ExpectedIdx) 1233 } 1234 if offset != c.ExpectedOffset { 1235 t.Fatalf("case %d: Got offset %d; want %d", i, offset, c.ExpectedOffset) 1236 } 1237 } 1238 }