github.com/lxpollitt/docker@v1.5.0/integration-cli/docker_cli_logs_test.go (about) 1 package main 2 3 import ( 4 "fmt" 5 "os/exec" 6 "regexp" 7 "strings" 8 "testing" 9 "time" 10 11 "github.com/docker/docker/pkg/timeutils" 12 ) 13 14 // This used to work, it test a log of PageSize-1 (gh#4851) 15 func TestLogsContainerSmallerThanPage(t *testing.T) { 16 testLen := 32767 17 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen)) 18 out, _, _, err := runCommandWithStdoutStderr(runCmd) 19 if err != nil { 20 t.Fatalf("run failed with errors: %s, %v", out, err) 21 } 22 23 cleanedContainerID := stripTrailingCharacters(out) 24 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 25 26 logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID) 27 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 28 if err != nil { 29 t.Fatalf("failed to log container: %s, %v", out, err) 30 } 31 32 if len(out) != testLen+1 { 33 t.Fatalf("Expected log length of %d, received %d\n", testLen+1, len(out)) 34 } 35 36 deleteContainer(cleanedContainerID) 37 38 logDone("logs - logs container running echo smaller than page size") 39 } 40 41 // Regression test: When going over the PageSize, it used to panic (gh#4851) 42 func TestLogsContainerBiggerThanPage(t *testing.T) { 43 testLen := 32768 44 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen)) 45 out, _, _, err := runCommandWithStdoutStderr(runCmd) 46 if err != nil { 47 t.Fatalf("run failed with errors: %s, %v", out, err) 48 } 49 50 cleanedContainerID := stripTrailingCharacters(out) 51 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 52 53 logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID) 54 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 55 if err != nil { 56 t.Fatalf("failed to log container: %s, %v", out, err) 57 } 58 59 if len(out) != testLen+1 { 60 t.Fatalf("Expected log length of %d, received %d\n", testLen+1, len(out)) 61 } 62 63 deleteContainer(cleanedContainerID) 64 65 logDone("logs - logs container running echo bigger than page size") 66 } 67 68 // Regression test: When going much over the PageSize, it used to block (gh#4851) 69 func TestLogsContainerMuchBiggerThanPage(t *testing.T) { 70 testLen := 33000 71 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo -n =; done; echo", testLen)) 72 out, _, _, err := runCommandWithStdoutStderr(runCmd) 73 if err != nil { 74 t.Fatalf("run failed with errors: %s, %v", out, err) 75 } 76 77 cleanedContainerID := stripTrailingCharacters(out) 78 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 79 80 logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID) 81 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 82 if err != nil { 83 t.Fatalf("failed to log container: %s, %v", out, err) 84 } 85 86 if len(out) != testLen+1 { 87 t.Fatalf("Expected log length of %d, received %d\n", testLen+1, len(out)) 88 } 89 90 deleteContainer(cleanedContainerID) 91 92 logDone("logs - logs container running echo much bigger than page size") 93 } 94 95 func TestLogsTimestamps(t *testing.T) { 96 testLen := 100 97 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo =; done;", testLen)) 98 99 out, _, _, err := runCommandWithStdoutStderr(runCmd) 100 if err != nil { 101 t.Fatalf("run failed with errors: %s, %v", out, err) 102 } 103 104 cleanedContainerID := stripTrailingCharacters(out) 105 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 106 107 logsCmd := exec.Command(dockerBinary, "logs", "-t", cleanedContainerID) 108 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 109 if err != nil { 110 t.Fatalf("failed to log container: %s, %v", out, err) 111 } 112 113 lines := strings.Split(out, "\n") 114 115 if len(lines) != testLen+1 { 116 t.Fatalf("Expected log %d lines, received %d\n", testLen+1, len(lines)) 117 } 118 119 ts := regexp.MustCompile(`^.* `) 120 121 for _, l := range lines { 122 if l != "" { 123 _, err := time.Parse(timeutils.RFC3339NanoFixed+" ", ts.FindString(l)) 124 if err != nil { 125 t.Fatalf("Failed to parse timestamp from %v: %v", l, err) 126 } 127 if l[29] != 'Z' { // ensure we have padded 0's 128 t.Fatalf("Timestamp isn't padded properly: %s", l) 129 } 130 } 131 } 132 133 deleteContainer(cleanedContainerID) 134 135 logDone("logs - logs with timestamps") 136 } 137 138 func TestLogsSeparateStderr(t *testing.T) { 139 msg := "stderr_log" 140 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg)) 141 142 out, _, _, err := runCommandWithStdoutStderr(runCmd) 143 if err != nil { 144 t.Fatalf("run failed with errors: %s, %v", out, err) 145 } 146 147 cleanedContainerID := stripTrailingCharacters(out) 148 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 149 150 logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID) 151 stdout, stderr, _, err := runCommandWithStdoutStderr(logsCmd) 152 if err != nil { 153 t.Fatalf("failed to log container: %s, %v", out, err) 154 } 155 156 if stdout != "" { 157 t.Fatalf("Expected empty stdout stream, got %v", stdout) 158 } 159 160 stderr = strings.TrimSpace(stderr) 161 if stderr != msg { 162 t.Fatalf("Expected %v in stderr stream, got %v", msg, stderr) 163 } 164 165 deleteContainer(cleanedContainerID) 166 167 logDone("logs - separate stderr (without pseudo-tty)") 168 } 169 170 func TestLogsStderrInStdout(t *testing.T) { 171 msg := "stderr_log" 172 runCmd := exec.Command(dockerBinary, "run", "-d", "-t", "busybox", "sh", "-c", fmt.Sprintf("echo %s 1>&2", msg)) 173 174 out, _, _, err := runCommandWithStdoutStderr(runCmd) 175 if err != nil { 176 t.Fatalf("run failed with errors: %s, %v", out, err) 177 } 178 179 cleanedContainerID := stripTrailingCharacters(out) 180 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 181 182 logsCmd := exec.Command(dockerBinary, "logs", cleanedContainerID) 183 stdout, stderr, _, err := runCommandWithStdoutStderr(logsCmd) 184 if err != nil { 185 t.Fatalf("failed to log container: %s, %v", out, err) 186 } 187 188 if stderr != "" { 189 t.Fatalf("Expected empty stderr stream, got %v", stdout) 190 } 191 192 stdout = strings.TrimSpace(stdout) 193 if stdout != msg { 194 t.Fatalf("Expected %v in stdout stream, got %v", msg, stdout) 195 } 196 197 deleteContainer(cleanedContainerID) 198 199 logDone("logs - stderr in stdout (with pseudo-tty)") 200 } 201 202 func TestLogsTail(t *testing.T) { 203 testLen := 100 204 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "sh", "-c", fmt.Sprintf("for i in $(seq 1 %d); do echo =; done;", testLen)) 205 206 out, _, _, err := runCommandWithStdoutStderr(runCmd) 207 if err != nil { 208 t.Fatalf("run failed with errors: %s, %v", out, err) 209 } 210 211 cleanedContainerID := stripTrailingCharacters(out) 212 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 213 214 logsCmd := exec.Command(dockerBinary, "logs", "--tail", "5", cleanedContainerID) 215 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 216 if err != nil { 217 t.Fatalf("failed to log container: %s, %v", out, err) 218 } 219 220 lines := strings.Split(out, "\n") 221 222 if len(lines) != 6 { 223 t.Fatalf("Expected log %d lines, received %d\n", 6, len(lines)) 224 } 225 226 logsCmd = exec.Command(dockerBinary, "logs", "--tail", "all", cleanedContainerID) 227 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 228 if err != nil { 229 t.Fatalf("failed to log container: %s, %v", out, err) 230 } 231 232 lines = strings.Split(out, "\n") 233 234 if len(lines) != testLen+1 { 235 t.Fatalf("Expected log %d lines, received %d\n", testLen+1, len(lines)) 236 } 237 238 logsCmd = exec.Command(dockerBinary, "logs", "--tail", "random", cleanedContainerID) 239 out, _, _, err = runCommandWithStdoutStderr(logsCmd) 240 if err != nil { 241 t.Fatalf("failed to log container: %s, %v", out, err) 242 } 243 244 lines = strings.Split(out, "\n") 245 246 if len(lines) != testLen+1 { 247 t.Fatalf("Expected log %d lines, received %d\n", testLen+1, len(lines)) 248 } 249 250 deleteContainer(cleanedContainerID) 251 logDone("logs - logs tail") 252 } 253 254 func TestLogsFollowStopped(t *testing.T) { 255 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "echo", "hello") 256 257 out, _, _, err := runCommandWithStdoutStderr(runCmd) 258 if err != nil { 259 t.Fatalf("run failed with errors: %s, %v", out, err) 260 } 261 262 cleanedContainerID := stripTrailingCharacters(out) 263 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 264 265 logsCmd := exec.Command(dockerBinary, "logs", "-f", cleanedContainerID) 266 if err := logsCmd.Start(); err != nil { 267 t.Fatal(err) 268 } 269 270 c := make(chan struct{}) 271 go func() { 272 if err := logsCmd.Wait(); err != nil { 273 t.Fatal(err) 274 } 275 close(c) 276 }() 277 278 select { 279 case <-c: 280 case <-time.After(1 * time.Second): 281 t.Fatal("Following logs is hanged") 282 } 283 284 deleteContainer(cleanedContainerID) 285 logDone("logs - logs follow stopped container") 286 } 287 288 // Regression test for #8832 289 func TestLogsFollowSlowStdoutConsumer(t *testing.T) { 290 runCmd := exec.Command(dockerBinary, "run", "-d", "busybox", "/bin/sh", "-c", `usleep 200000;yes X | head -c 200000`) 291 292 out, _, _, err := runCommandWithStdoutStderr(runCmd) 293 if err != nil { 294 t.Fatalf("run failed with errors: %s, %v", out, err) 295 } 296 297 cleanedContainerID := stripTrailingCharacters(out) 298 defer deleteContainer(cleanedContainerID) 299 300 stopSlowRead := make(chan bool) 301 302 go func() { 303 exec.Command(dockerBinary, "wait", cleanedContainerID).Run() 304 stopSlowRead <- true 305 }() 306 307 logCmd := exec.Command(dockerBinary, "logs", "-f", cleanedContainerID) 308 309 stdout, err := logCmd.StdoutPipe() 310 if err != nil { 311 t.Fatal(err) 312 } 313 314 if err := logCmd.Start(); err != nil { 315 t.Fatal(err) 316 } 317 318 // First read slowly 319 bytes1, err := consumeWithSpeed(stdout, 10, 50*time.Millisecond, stopSlowRead) 320 if err != nil { 321 t.Fatal(err) 322 } 323 324 // After the container has finished we can continue reading fast 325 bytes2, err := consumeWithSpeed(stdout, 32*1024, 0, nil) 326 if err != nil { 327 t.Fatal(err) 328 } 329 330 actual := bytes1 + bytes2 331 expected := 200000 332 if actual != expected { 333 t.Fatalf("Invalid bytes read: %d, expected %d", actual, expected) 334 } 335 336 logDone("logs - follow slow consumer") 337 }