11693: Add test cases for symlinks to directories and symlinks inside subdirectories.
[arvados.git] / services / crunch-run / crunchrun_test.go
1 package main
2
3 import (
4         "bufio"
5         "bytes"
6         "context"
7         "crypto/md5"
8         "encoding/json"
9         "errors"
10         "fmt"
11         "io"
12         "io/ioutil"
13         "log"
14         "net"
15         "os"
16         "os/exec"
17         "path/filepath"
18         "runtime/pprof"
19         "sort"
20         "strings"
21         "sync"
22         "syscall"
23         "testing"
24         "time"
25
26         "git.curoverse.com/arvados.git/sdk/go/arvados"
27         "git.curoverse.com/arvados.git/sdk/go/arvadosclient"
28         "git.curoverse.com/arvados.git/sdk/go/keepclient"
29         "git.curoverse.com/arvados.git/sdk/go/manifest"
30
31         dockertypes "github.com/docker/docker/api/types"
32         dockercontainer "github.com/docker/docker/api/types/container"
33         dockernetwork "github.com/docker/docker/api/types/network"
34         . "gopkg.in/check.v1"
35 )
36
37 // Gocheck boilerplate
38 func TestCrunchExec(t *testing.T) {
39         TestingT(t)
40 }
41
42 type TestSuite struct{}
43
44 // Gocheck boilerplate
45 var _ = Suite(&TestSuite{})
46
47 type ArvTestClient struct {
48         Total   int64
49         Calls   int
50         Content []arvadosclient.Dict
51         arvados.Container
52         Logs map[string]*bytes.Buffer
53         sync.Mutex
54         WasSetRunning bool
55 }
56
57 type KeepTestClient struct {
58         Called  bool
59         Content []byte
60 }
61
62 var hwManifest = ". 82ab40c24fc8df01798e57ba66795bb1+841216+Aa124ac75e5168396c73c0a18eda641a4f41791c0@569fa8c3 0:841216:9c31ee32b3d15268a0754e8edc74d4f815ee014b693bc5109058e431dd5caea7.tar\n"
63 var hwPDH = "a45557269dcb65a6b78f9ac061c0850b+120"
64 var hwImageId = "9c31ee32b3d15268a0754e8edc74d4f815ee014b693bc5109058e431dd5caea7"
65
66 var otherManifest = ". 68a84f561b1d1708c6baff5e019a9ab3+46+Ae5d0af96944a3690becb1decdf60cc1c937f556d@5693216f 0:46:md5sum.txt\n"
67 var otherPDH = "a3e8f74c6f101eae01fa08bfb4e49b3a+54"
68
69 var normalizedManifestWithSubdirs = `. 3e426d509afffb85e06c4c96a7c15e91+27+Aa124ac75e5168396c73c0abcdefgh11234567890@569fa8c3 0:9:file1_in_main.txt 9:18:file2_in_main.txt 0:27:zzzzz-8i9sb-bcdefghijkdhvnk.log.txt
70 ./subdir1 3e426d509afffb85e06c4c96a7c15e91+27+Aa124ac75e5168396cabcdefghij6419876543234@569fa8c4 0:9:file1_in_subdir1.txt 9:18:file2_in_subdir1.txt
71 ./subdir1/subdir2 3e426d509afffb85e06c4c96a7c15e91+27+Aa124ac75e5168396c73c0bcdefghijk544332211@569fa8c5 0:9:file1_in_subdir2.txt 9:18:file2_in_subdir2.txt
72 `
73
74 var normalizedWithSubdirsPDH = "a0def87f80dd594d4675809e83bd4f15+367"
75
76 var denormalizedManifestWithSubdirs = ". 3e426d509afffb85e06c4c96a7c15e91+27+Aa124ac75e5168396c73c0abcdefgh11234567890@569fa8c3 0:9:file1_in_main.txt 9:18:file2_in_main.txt 0:27:zzzzz-8i9sb-bcdefghijkdhvnk.log.txt 0:10:subdir1/file1_in_subdir1.txt 10:17:subdir1/file2_in_subdir1.txt\n"
77 var denormalizedWithSubdirsPDH = "b0def87f80dd594d4675809e83bd4f15+367"
78
79 var fakeAuthUUID = "zzzzz-gj3su-55pqoyepgi2glem"
80 var fakeAuthToken = "a3ltuwzqcu2u4sc0q7yhpc2w7s00fdcqecg5d6e0u3pfohmbjt"
81
82 type TestDockerClient struct {
83         imageLoaded string
84         logReader   io.ReadCloser
85         logWriter   io.WriteCloser
86         fn          func(t *TestDockerClient)
87         finish      int
88         stop        chan bool
89         cwd         string
90         env         []string
91         api         *ArvTestClient
92         realTemp    string
93 }
94
95 func NewTestDockerClient(exitCode int) *TestDockerClient {
96         t := &TestDockerClient{}
97         t.logReader, t.logWriter = io.Pipe()
98         t.finish = exitCode
99         t.stop = make(chan bool)
100         t.cwd = "/"
101         return t
102 }
103
104 type MockConn struct {
105         net.Conn
106 }
107
108 func (m *MockConn) Write(b []byte) (int, error) {
109         return len(b), nil
110 }
111
112 func NewMockConn() *MockConn {
113         c := &MockConn{}
114         return c
115 }
116
117 func (t *TestDockerClient) ContainerAttach(ctx context.Context, container string, options dockertypes.ContainerAttachOptions) (dockertypes.HijackedResponse, error) {
118         return dockertypes.HijackedResponse{Conn: NewMockConn(), Reader: bufio.NewReader(t.logReader)}, nil
119 }
120
121 func (t *TestDockerClient) ContainerCreate(ctx context.Context, config *dockercontainer.Config, hostConfig *dockercontainer.HostConfig, networkingConfig *dockernetwork.NetworkingConfig, containerName string) (dockercontainer.ContainerCreateCreatedBody, error) {
122         if config.WorkingDir != "" {
123                 t.cwd = config.WorkingDir
124         }
125         t.env = config.Env
126         return dockercontainer.ContainerCreateCreatedBody{ID: "abcde"}, nil
127 }
128
129 func (t *TestDockerClient) ContainerStart(ctx context.Context, container string, options dockertypes.ContainerStartOptions) error {
130         if container == "abcde" {
131                 go t.fn(t)
132                 return nil
133         } else {
134                 return errors.New("Invalid container id")
135         }
136 }
137
138 func (t *TestDockerClient) ContainerStop(ctx context.Context, container string, timeout *time.Duration) error {
139         t.stop <- true
140         return nil
141 }
142
143 func (t *TestDockerClient) ContainerWait(ctx context.Context, container string) (int64, error) {
144         return int64(t.finish), nil
145 }
146
147 func (t *TestDockerClient) ImageInspectWithRaw(ctx context.Context, image string) (dockertypes.ImageInspect, []byte, error) {
148         if t.imageLoaded == image {
149                 return dockertypes.ImageInspect{}, nil, nil
150         } else {
151                 return dockertypes.ImageInspect{}, nil, errors.New("")
152         }
153 }
154
155 func (t *TestDockerClient) ImageLoad(ctx context.Context, input io.Reader, quiet bool) (dockertypes.ImageLoadResponse, error) {
156         _, err := io.Copy(ioutil.Discard, input)
157         if err != nil {
158                 return dockertypes.ImageLoadResponse{}, err
159         } else {
160                 t.imageLoaded = hwImageId
161                 return dockertypes.ImageLoadResponse{Body: ioutil.NopCloser(input)}, nil
162         }
163 }
164
165 func (*TestDockerClient) ImageRemove(ctx context.Context, image string, options dockertypes.ImageRemoveOptions) ([]dockertypes.ImageDeleteResponseItem, error) {
166         return nil, nil
167 }
168
169 func (client *ArvTestClient) Create(resourceType string,
170         parameters arvadosclient.Dict,
171         output interface{}) error {
172
173         client.Mutex.Lock()
174         defer client.Mutex.Unlock()
175
176         client.Calls++
177         client.Content = append(client.Content, parameters)
178
179         if resourceType == "logs" {
180                 et := parameters["log"].(arvadosclient.Dict)["event_type"].(string)
181                 if client.Logs == nil {
182                         client.Logs = make(map[string]*bytes.Buffer)
183                 }
184                 if client.Logs[et] == nil {
185                         client.Logs[et] = &bytes.Buffer{}
186                 }
187                 client.Logs[et].Write([]byte(parameters["log"].(arvadosclient.Dict)["properties"].(map[string]string)["text"]))
188         }
189
190         if resourceType == "collections" && output != nil {
191                 mt := parameters["collection"].(arvadosclient.Dict)["manifest_text"].(string)
192                 outmap := output.(*arvados.Collection)
193                 outmap.PortableDataHash = fmt.Sprintf("%x+%d", md5.Sum([]byte(mt)), len(mt))
194         }
195
196         return nil
197 }
198
199 func (client *ArvTestClient) Call(method, resourceType, uuid, action string, parameters arvadosclient.Dict, output interface{}) error {
200         switch {
201         case method == "GET" && resourceType == "containers" && action == "auth":
202                 return json.Unmarshal([]byte(`{
203                         "kind": "arvados#api_client_authorization",
204                         "uuid": "`+fakeAuthUUID+`",
205                         "api_token": "`+fakeAuthToken+`"
206                         }`), output)
207         default:
208                 return fmt.Errorf("Not found")
209         }
210 }
211
212 func (client *ArvTestClient) CallRaw(method, resourceType, uuid, action string,
213         parameters arvadosclient.Dict) (reader io.ReadCloser, err error) {
214         j := []byte(`{
215                 "command": ["sleep", "1"],
216                 "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
217                 "cwd": ".",
218                 "environment": {},
219                 "mounts": {"/tmp": {"kind": "tmp"} },
220                 "output_path": "/tmp",
221                 "priority": 1,
222                 "runtime_constraints": {}
223         }`)
224         return ioutil.NopCloser(bytes.NewReader(j)), nil
225 }
226
227 func (client *ArvTestClient) Get(resourceType string, uuid string, parameters arvadosclient.Dict, output interface{}) error {
228         if resourceType == "collections" {
229                 if uuid == hwPDH {
230                         output.(*arvados.Collection).ManifestText = hwManifest
231                 } else if uuid == otherPDH {
232                         output.(*arvados.Collection).ManifestText = otherManifest
233                 } else if uuid == normalizedWithSubdirsPDH {
234                         output.(*arvados.Collection).ManifestText = normalizedManifestWithSubdirs
235                 } else if uuid == denormalizedWithSubdirsPDH {
236                         output.(*arvados.Collection).ManifestText = denormalizedManifestWithSubdirs
237                 }
238         }
239         if resourceType == "containers" {
240                 (*output.(*arvados.Container)) = client.Container
241         }
242         return nil
243 }
244
245 func (client *ArvTestClient) Update(resourceType string, uuid string, parameters arvadosclient.Dict, output interface{}) (err error) {
246         client.Mutex.Lock()
247         defer client.Mutex.Unlock()
248         client.Calls++
249         client.Content = append(client.Content, parameters)
250         if resourceType == "containers" {
251                 if parameters["container"].(arvadosclient.Dict)["state"] == "Running" {
252                         client.WasSetRunning = true
253                 }
254         }
255         return nil
256 }
257
258 var discoveryMap = map[string]interface{}{
259         "defaultTrashLifetime":               float64(1209600),
260         "crunchLimitLogBytesPerJob":          float64(67108864),
261         "crunchLogThrottleBytes":             float64(65536),
262         "crunchLogThrottlePeriod":            float64(60),
263         "crunchLogThrottleLines":             float64(1024),
264         "crunchLogPartialLineThrottlePeriod": float64(5),
265         "crunchLogBytesPerEvent":             float64(4096),
266         "crunchLogSecondsBetweenEvents":      float64(1),
267 }
268
269 func (client *ArvTestClient) Discovery(key string) (interface{}, error) {
270         return discoveryMap[key], nil
271 }
272
273 // CalledWith returns the parameters from the first API call whose
274 // parameters match jpath/string. E.g., CalledWith(c, "foo.bar",
275 // "baz") returns parameters with parameters["foo"]["bar"]=="baz". If
276 // no call matches, it returns nil.
277 func (client *ArvTestClient) CalledWith(jpath string, expect interface{}) arvadosclient.Dict {
278 call:
279         for _, content := range client.Content {
280                 var v interface{} = content
281                 for _, k := range strings.Split(jpath, ".") {
282                         if dict, ok := v.(arvadosclient.Dict); !ok {
283                                 continue call
284                         } else {
285                                 v = dict[k]
286                         }
287                 }
288                 if v == expect {
289                         return content
290                 }
291         }
292         return nil
293 }
294
295 func (client *KeepTestClient) PutHB(hash string, buf []byte) (string, int, error) {
296         client.Content = buf
297         return fmt.Sprintf("%s+%d", hash, len(buf)), len(buf), nil
298 }
299
300 type FileWrapper struct {
301         io.ReadCloser
302         len uint64
303 }
304
305 func (fw FileWrapper) Len() uint64 {
306         return fw.len
307 }
308
309 func (fw FileWrapper) Seek(int64, int) (int64, error) {
310         return 0, errors.New("not implemented")
311 }
312
313 func (client *KeepTestClient) ManifestFileReader(m manifest.Manifest, filename string) (keepclient.Reader, error) {
314         if filename == hwImageId+".tar" {
315                 rdr := ioutil.NopCloser(&bytes.Buffer{})
316                 client.Called = true
317                 return FileWrapper{rdr, 1321984}, nil
318         } else if filename == "/file1_in_main.txt" {
319                 rdr := ioutil.NopCloser(strings.NewReader("foo"))
320                 client.Called = true
321                 return FileWrapper{rdr, 3}, nil
322         }
323         return nil, nil
324 }
325
326 func (s *TestSuite) TestLoadImage(c *C) {
327         kc := &KeepTestClient{}
328         docker := NewTestDockerClient(0)
329         cr := NewContainerRunner(&ArvTestClient{}, kc, docker, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
330
331         _, err := cr.Docker.ImageRemove(nil, hwImageId, dockertypes.ImageRemoveOptions{})
332
333         _, _, err = cr.Docker.ImageInspectWithRaw(nil, hwImageId)
334         c.Check(err, NotNil)
335
336         cr.Container.ContainerImage = hwPDH
337
338         // (1) Test loading image from keep
339         c.Check(kc.Called, Equals, false)
340         c.Check(cr.ContainerConfig.Image, Equals, "")
341
342         err = cr.LoadImage()
343
344         c.Check(err, IsNil)
345         defer func() {
346                 cr.Docker.ImageRemove(nil, hwImageId, dockertypes.ImageRemoveOptions{})
347         }()
348
349         c.Check(kc.Called, Equals, true)
350         c.Check(cr.ContainerConfig.Image, Equals, hwImageId)
351
352         _, _, err = cr.Docker.ImageInspectWithRaw(nil, hwImageId)
353         c.Check(err, IsNil)
354
355         // (2) Test using image that's already loaded
356         kc.Called = false
357         cr.ContainerConfig.Image = ""
358
359         err = cr.LoadImage()
360         c.Check(err, IsNil)
361         c.Check(kc.Called, Equals, false)
362         c.Check(cr.ContainerConfig.Image, Equals, hwImageId)
363
364 }
365
366 type ArvErrorTestClient struct{}
367
368 func (ArvErrorTestClient) Create(resourceType string,
369         parameters arvadosclient.Dict,
370         output interface{}) error {
371         return nil
372 }
373
374 func (ArvErrorTestClient) Call(method, resourceType, uuid, action string, parameters arvadosclient.Dict, output interface{}) error {
375         return errors.New("ArvError")
376 }
377
378 func (ArvErrorTestClient) CallRaw(method, resourceType, uuid, action string,
379         parameters arvadosclient.Dict) (reader io.ReadCloser, err error) {
380         return nil, errors.New("ArvError")
381 }
382
383 func (ArvErrorTestClient) Get(resourceType string, uuid string, parameters arvadosclient.Dict, output interface{}) error {
384         return errors.New("ArvError")
385 }
386
387 func (ArvErrorTestClient) Update(resourceType string, uuid string, parameters arvadosclient.Dict, output interface{}) (err error) {
388         return nil
389 }
390
391 func (ArvErrorTestClient) Discovery(key string) (interface{}, error) {
392         return discoveryMap[key], nil
393 }
394
395 type KeepErrorTestClient struct{}
396
397 func (KeepErrorTestClient) PutHB(hash string, buf []byte) (string, int, error) {
398         return "", 0, errors.New("KeepError")
399 }
400
401 func (KeepErrorTestClient) ManifestFileReader(m manifest.Manifest, filename string) (keepclient.Reader, error) {
402         return nil, errors.New("KeepError")
403 }
404
405 type KeepReadErrorTestClient struct{}
406
407 func (KeepReadErrorTestClient) PutHB(hash string, buf []byte) (string, int, error) {
408         return "", 0, nil
409 }
410
411 type ErrorReader struct{}
412
413 func (ErrorReader) Read(p []byte) (n int, err error) {
414         return 0, errors.New("ErrorReader")
415 }
416
417 func (ErrorReader) Close() error {
418         return nil
419 }
420
421 func (ErrorReader) Len() uint64 {
422         return 0
423 }
424
425 func (ErrorReader) Seek(int64, int) (int64, error) {
426         return 0, errors.New("ErrorReader")
427 }
428
429 func (KeepReadErrorTestClient) ManifestFileReader(m manifest.Manifest, filename string) (keepclient.Reader, error) {
430         return ErrorReader{}, nil
431 }
432
433 func (s *TestSuite) TestLoadImageArvError(c *C) {
434         // (1) Arvados error
435         cr := NewContainerRunner(ArvErrorTestClient{}, &KeepTestClient{}, nil, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
436         cr.Container.ContainerImage = hwPDH
437
438         err := cr.LoadImage()
439         c.Check(err.Error(), Equals, "While getting container image collection: ArvError")
440 }
441
442 func (s *TestSuite) TestLoadImageKeepError(c *C) {
443         // (2) Keep error
444         docker := NewTestDockerClient(0)
445         cr := NewContainerRunner(&ArvTestClient{}, KeepErrorTestClient{}, docker, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
446         cr.Container.ContainerImage = hwPDH
447
448         err := cr.LoadImage()
449         c.Check(err.Error(), Equals, "While creating ManifestFileReader for container image: KeepError")
450 }
451
452 func (s *TestSuite) TestLoadImageCollectionError(c *C) {
453         // (3) Collection doesn't contain image
454         cr := NewContainerRunner(&ArvTestClient{}, KeepErrorTestClient{}, nil, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
455         cr.Container.ContainerImage = otherPDH
456
457         err := cr.LoadImage()
458         c.Check(err.Error(), Equals, "First file in the container image collection does not end in .tar")
459 }
460
461 func (s *TestSuite) TestLoadImageKeepReadError(c *C) {
462         // (4) Collection doesn't contain image
463         docker := NewTestDockerClient(0)
464         cr := NewContainerRunner(&ArvTestClient{}, KeepReadErrorTestClient{}, docker, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
465         cr.Container.ContainerImage = hwPDH
466
467         err := cr.LoadImage()
468         c.Check(err, NotNil)
469 }
470
471 type ClosableBuffer struct {
472         bytes.Buffer
473 }
474
475 func (*ClosableBuffer) Close() error {
476         return nil
477 }
478
479 type TestLogs struct {
480         Stdout ClosableBuffer
481         Stderr ClosableBuffer
482 }
483
484 func (tl *TestLogs) NewTestLoggingWriter(logstr string) io.WriteCloser {
485         if logstr == "stdout" {
486                 return &tl.Stdout
487         }
488         if logstr == "stderr" {
489                 return &tl.Stderr
490         }
491         return nil
492 }
493
494 func dockerLog(fd byte, msg string) []byte {
495         by := []byte(msg)
496         header := make([]byte, 8+len(by))
497         header[0] = fd
498         header[7] = byte(len(by))
499         copy(header[8:], by)
500         return header
501 }
502
503 func (s *TestSuite) TestRunContainer(c *C) {
504         docker := NewTestDockerClient(0)
505         docker.fn = func(t *TestDockerClient) {
506                 t.logWriter.Write(dockerLog(1, "Hello world\n"))
507                 t.logWriter.Close()
508         }
509         cr := NewContainerRunner(&ArvTestClient{}, &KeepTestClient{}, docker, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
510
511         var logs TestLogs
512         cr.NewLogWriter = logs.NewTestLoggingWriter
513         cr.Container.ContainerImage = hwPDH
514         cr.Container.Command = []string{"./hw"}
515         err := cr.LoadImage()
516         c.Check(err, IsNil)
517
518         err = cr.CreateContainer()
519         c.Check(err, IsNil)
520
521         err = cr.StartContainer()
522         c.Check(err, IsNil)
523
524         err = cr.WaitFinish()
525         c.Check(err, IsNil)
526
527         c.Check(strings.HasSuffix(logs.Stdout.String(), "Hello world\n"), Equals, true)
528         c.Check(logs.Stderr.String(), Equals, "")
529 }
530
531 func (s *TestSuite) TestCommitLogs(c *C) {
532         api := &ArvTestClient{}
533         kc := &KeepTestClient{}
534         cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
535         cr.CrunchLog.Timestamper = (&TestTimestamper{}).Timestamp
536
537         cr.CrunchLog.Print("Hello world!")
538         cr.CrunchLog.Print("Goodbye")
539         cr.finalState = "Complete"
540
541         err := cr.CommitLogs()
542         c.Check(err, IsNil)
543
544         c.Check(api.Calls, Equals, 2)
545         c.Check(api.Content[1]["ensure_unique_name"], Equals, true)
546         c.Check(api.Content[1]["collection"].(arvadosclient.Dict)["name"], Equals, "logs for zzzzz-zzzzz-zzzzzzzzzzzzzzz")
547         c.Check(api.Content[1]["collection"].(arvadosclient.Dict)["manifest_text"], Equals, ". 744b2e4553123b02fa7b452ec5c18993+123 0:123:crunch-run.txt\n")
548         c.Check(*cr.LogsPDH, Equals, "63da7bdacf08c40f604daad80c261e9a+60")
549 }
550
551 func (s *TestSuite) TestUpdateContainerRunning(c *C) {
552         api := &ArvTestClient{}
553         kc := &KeepTestClient{}
554         cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
555
556         err := cr.UpdateContainerRunning()
557         c.Check(err, IsNil)
558
559         c.Check(api.Content[0]["container"].(arvadosclient.Dict)["state"], Equals, "Running")
560 }
561
562 func (s *TestSuite) TestUpdateContainerComplete(c *C) {
563         api := &ArvTestClient{}
564         kc := &KeepTestClient{}
565         cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
566
567         cr.LogsPDH = new(string)
568         *cr.LogsPDH = "d3a229d2fe3690c2c3e75a71a153c6a3+60"
569
570         cr.ExitCode = new(int)
571         *cr.ExitCode = 42
572         cr.finalState = "Complete"
573
574         err := cr.UpdateContainerFinal()
575         c.Check(err, IsNil)
576
577         c.Check(api.Content[0]["container"].(arvadosclient.Dict)["log"], Equals, *cr.LogsPDH)
578         c.Check(api.Content[0]["container"].(arvadosclient.Dict)["exit_code"], Equals, *cr.ExitCode)
579         c.Check(api.Content[0]["container"].(arvadosclient.Dict)["state"], Equals, "Complete")
580 }
581
582 func (s *TestSuite) TestUpdateContainerCancelled(c *C) {
583         api := &ArvTestClient{}
584         kc := &KeepTestClient{}
585         cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
586         cr.cCancelled = true
587         cr.finalState = "Cancelled"
588
589         err := cr.UpdateContainerFinal()
590         c.Check(err, IsNil)
591
592         c.Check(api.Content[0]["container"].(arvadosclient.Dict)["log"], IsNil)
593         c.Check(api.Content[0]["container"].(arvadosclient.Dict)["exit_code"], IsNil)
594         c.Check(api.Content[0]["container"].(arvadosclient.Dict)["state"], Equals, "Cancelled")
595 }
596
597 // Used by the TestFullRun*() test below to DRY up boilerplate setup to do full
598 // dress rehearsal of the Run() function, starting from a JSON container record.
599 func FullRunHelper(c *C, record string, extraMounts []string, exitCode int, fn func(t *TestDockerClient)) (api *ArvTestClient, cr *ContainerRunner, realTemp string) {
600         rec := arvados.Container{}
601         err := json.Unmarshal([]byte(record), &rec)
602         c.Check(err, IsNil)
603
604         docker := NewTestDockerClient(exitCode)
605         docker.fn = fn
606         docker.ImageRemove(nil, hwImageId, dockertypes.ImageRemoveOptions{})
607
608         api = &ArvTestClient{Container: rec}
609         docker.api = api
610         cr = NewContainerRunner(api, &KeepTestClient{}, docker, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
611         cr.statInterval = 100 * time.Millisecond
612         am := &ArvMountCmdLine{}
613         cr.RunArvMount = am.ArvMountTest
614
615         realTemp, err = ioutil.TempDir("", "crunchrun_test1-")
616         c.Assert(err, IsNil)
617         defer os.RemoveAll(realTemp)
618
619         docker.realTemp = realTemp
620
621         tempcount := 0
622         cr.MkTempDir = func(_ string, prefix string) (string, error) {
623                 tempcount++
624                 d := fmt.Sprintf("%s/%s%d", realTemp, prefix, tempcount)
625                 err := os.Mkdir(d, os.ModePerm)
626                 if err != nil && strings.Contains(err.Error(), ": file exists") {
627                         // Test case must have pre-populated the tempdir
628                         err = nil
629                 }
630                 return d, err
631         }
632
633         if extraMounts != nil && len(extraMounts) > 0 {
634                 err := cr.SetupArvMountPoint("keep")
635                 c.Check(err, IsNil)
636
637                 for _, m := range extraMounts {
638                         os.MkdirAll(cr.ArvMountPoint+"/by_id/"+m, os.ModePerm)
639                 }
640         }
641
642         err = cr.Run()
643         c.Check(err, IsNil)
644         c.Check(api.WasSetRunning, Equals, true)
645
646         c.Check(api.Content[api.Calls-1]["container"].(arvadosclient.Dict)["log"], NotNil)
647
648         if err != nil {
649                 for k, v := range api.Logs {
650                         c.Log(k)
651                         c.Log(v.String())
652                 }
653         }
654
655         return
656 }
657
658 func (s *TestSuite) TestFullRunHello(c *C) {
659         api, _, _ := FullRunHelper(c, `{
660     "command": ["echo", "hello world"],
661     "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
662     "cwd": ".",
663     "environment": {},
664     "mounts": {"/tmp": {"kind": "tmp"} },
665     "output_path": "/tmp",
666     "priority": 1,
667     "runtime_constraints": {}
668 }`, nil, 0, func(t *TestDockerClient) {
669                 t.logWriter.Write(dockerLog(1, "hello world\n"))
670                 t.logWriter.Close()
671         })
672
673         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
674         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
675         c.Check(strings.HasSuffix(api.Logs["stdout"].String(), "hello world\n"), Equals, true)
676
677 }
678
679 func (s *TestSuite) TestCrunchstat(c *C) {
680         api, _, _ := FullRunHelper(c, `{
681                 "command": ["sleep", "1"],
682                 "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
683                 "cwd": ".",
684                 "environment": {},
685                 "mounts": {"/tmp": {"kind": "tmp"} },
686                 "output_path": "/tmp",
687                 "priority": 1,
688                 "runtime_constraints": {}
689         }`, nil, 0, func(t *TestDockerClient) {
690                 time.Sleep(time.Second)
691                 t.logWriter.Close()
692         })
693
694         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
695         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
696
697         // We didn't actually start a container, so crunchstat didn't
698         // find accounting files and therefore didn't log any stats.
699         // It should have logged a "can't find accounting files"
700         // message after one poll interval, though, so we can confirm
701         // it's alive:
702         c.Assert(api.Logs["crunchstat"], NotNil)
703         c.Check(api.Logs["crunchstat"].String(), Matches, `(?ms).*cgroup stats files have not appeared after 100ms.*`)
704
705         // The "files never appeared" log assures us that we called
706         // (*crunchstat.Reporter)Stop(), and that we set it up with
707         // the correct container ID "abcde":
708         c.Check(api.Logs["crunchstat"].String(), Matches, `(?ms).*cgroup stats files never appeared for abcde\n`)
709 }
710
711 func (s *TestSuite) TestNodeInfoLog(c *C) {
712         api, _, _ := FullRunHelper(c, `{
713                 "command": ["sleep", "1"],
714                 "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
715                 "cwd": ".",
716                 "environment": {},
717                 "mounts": {"/tmp": {"kind": "tmp"} },
718                 "output_path": "/tmp",
719                 "priority": 1,
720                 "runtime_constraints": {}
721         }`, nil, 0,
722                 func(t *TestDockerClient) {
723                         time.Sleep(time.Second)
724                         t.logWriter.Close()
725                 })
726
727         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
728         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
729
730         c.Assert(api.Logs["node-info"], NotNil)
731         c.Check(api.Logs["node-info"].String(), Matches, `(?ms).*Host Information.*`)
732         c.Check(api.Logs["node-info"].String(), Matches, `(?ms).*CPU Information.*`)
733         c.Check(api.Logs["node-info"].String(), Matches, `(?ms).*Memory Information.*`)
734         c.Check(api.Logs["node-info"].String(), Matches, `(?ms).*Disk Space.*`)
735         c.Check(api.Logs["node-info"].String(), Matches, `(?ms).*Disk INodes.*`)
736 }
737
738 func (s *TestSuite) TestContainerRecordLog(c *C) {
739         api, _, _ := FullRunHelper(c, `{
740                 "command": ["sleep", "1"],
741                 "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
742                 "cwd": ".",
743                 "environment": {},
744                 "mounts": {"/tmp": {"kind": "tmp"} },
745                 "output_path": "/tmp",
746                 "priority": 1,
747                 "runtime_constraints": {}
748         }`, nil, 0,
749                 func(t *TestDockerClient) {
750                         time.Sleep(time.Second)
751                         t.logWriter.Close()
752                 })
753
754         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
755         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
756
757         c.Assert(api.Logs["container"], NotNil)
758         c.Check(api.Logs["container"].String(), Matches, `(?ms).*container_image.*`)
759 }
760
761 func (s *TestSuite) TestFullRunStderr(c *C) {
762         api, _, _ := FullRunHelper(c, `{
763     "command": ["/bin/sh", "-c", "echo hello ; echo world 1>&2 ; exit 1"],
764     "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
765     "cwd": ".",
766     "environment": {},
767     "mounts": {"/tmp": {"kind": "tmp"} },
768     "output_path": "/tmp",
769     "priority": 1,
770     "runtime_constraints": {}
771 }`, nil, 1, func(t *TestDockerClient) {
772                 t.logWriter.Write(dockerLog(1, "hello\n"))
773                 t.logWriter.Write(dockerLog(2, "world\n"))
774                 t.logWriter.Close()
775         })
776
777         final := api.CalledWith("container.state", "Complete")
778         c.Assert(final, NotNil)
779         c.Check(final["container"].(arvadosclient.Dict)["exit_code"], Equals, 1)
780         c.Check(final["container"].(arvadosclient.Dict)["log"], NotNil)
781
782         c.Check(strings.HasSuffix(api.Logs["stdout"].String(), "hello\n"), Equals, true)
783         c.Check(strings.HasSuffix(api.Logs["stderr"].String(), "world\n"), Equals, true)
784 }
785
786 func (s *TestSuite) TestFullRunDefaultCwd(c *C) {
787         api, _, _ := FullRunHelper(c, `{
788     "command": ["pwd"],
789     "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
790     "cwd": ".",
791     "environment": {},
792     "mounts": {"/tmp": {"kind": "tmp"} },
793     "output_path": "/tmp",
794     "priority": 1,
795     "runtime_constraints": {}
796 }`, nil, 0, func(t *TestDockerClient) {
797                 t.logWriter.Write(dockerLog(1, t.cwd+"\n"))
798                 t.logWriter.Close()
799         })
800
801         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
802         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
803         c.Log(api.Logs["stdout"])
804         c.Check(strings.HasSuffix(api.Logs["stdout"].String(), "/\n"), Equals, true)
805 }
806
807 func (s *TestSuite) TestFullRunSetCwd(c *C) {
808         api, _, _ := FullRunHelper(c, `{
809     "command": ["pwd"],
810     "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
811     "cwd": "/bin",
812     "environment": {},
813     "mounts": {"/tmp": {"kind": "tmp"} },
814     "output_path": "/tmp",
815     "priority": 1,
816     "runtime_constraints": {}
817 }`, nil, 0, func(t *TestDockerClient) {
818                 t.logWriter.Write(dockerLog(1, t.cwd+"\n"))
819                 t.logWriter.Close()
820         })
821
822         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
823         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
824         c.Check(strings.HasSuffix(api.Logs["stdout"].String(), "/bin\n"), Equals, true)
825 }
826
827 func (s *TestSuite) TestStopOnSignal(c *C) {
828         s.testStopContainer(c, func(cr *ContainerRunner) {
829                 go func() {
830                         for !cr.cStarted {
831                                 time.Sleep(time.Millisecond)
832                         }
833                         cr.SigChan <- syscall.SIGINT
834                 }()
835         })
836 }
837
838 func (s *TestSuite) TestStopOnArvMountDeath(c *C) {
839         s.testStopContainer(c, func(cr *ContainerRunner) {
840                 cr.ArvMountExit = make(chan error)
841                 go func() {
842                         cr.ArvMountExit <- exec.Command("true").Run()
843                         close(cr.ArvMountExit)
844                 }()
845         })
846 }
847
848 func (s *TestSuite) testStopContainer(c *C, setup func(cr *ContainerRunner)) {
849         record := `{
850     "command": ["/bin/sh", "-c", "echo foo && sleep 30 && echo bar"],
851     "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
852     "cwd": ".",
853     "environment": {},
854     "mounts": {"/tmp": {"kind": "tmp"} },
855     "output_path": "/tmp",
856     "priority": 1,
857     "runtime_constraints": {}
858 }`
859
860         rec := arvados.Container{}
861         err := json.Unmarshal([]byte(record), &rec)
862         c.Check(err, IsNil)
863
864         docker := NewTestDockerClient(0)
865         docker.fn = func(t *TestDockerClient) {
866                 <-t.stop
867                 t.logWriter.Write(dockerLog(1, "foo\n"))
868                 t.logWriter.Close()
869         }
870         docker.ImageRemove(nil, hwImageId, dockertypes.ImageRemoveOptions{})
871
872         api := &ArvTestClient{Container: rec}
873         cr := NewContainerRunner(api, &KeepTestClient{}, docker, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
874         cr.RunArvMount = func([]string, string) (*exec.Cmd, error) { return nil, nil }
875         setup(cr)
876
877         done := make(chan error)
878         go func() {
879                 done <- cr.Run()
880         }()
881         select {
882         case <-time.After(20 * time.Second):
883                 pprof.Lookup("goroutine").WriteTo(os.Stderr, 1)
884                 c.Fatal("timed out")
885         case err = <-done:
886                 c.Check(err, IsNil)
887         }
888         for k, v := range api.Logs {
889                 c.Log(k)
890                 c.Log(v.String())
891         }
892
893         c.Check(api.CalledWith("container.log", nil), NotNil)
894         c.Check(api.CalledWith("container.state", "Cancelled"), NotNil)
895         c.Check(strings.HasSuffix(api.Logs["stdout"].String(), "foo\n"), Equals, true)
896 }
897
898 func (s *TestSuite) TestFullRunSetEnv(c *C) {
899         api, _, _ := FullRunHelper(c, `{
900     "command": ["/bin/sh", "-c", "echo $FROBIZ"],
901     "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
902     "cwd": "/bin",
903     "environment": {"FROBIZ": "bilbo"},
904     "mounts": {"/tmp": {"kind": "tmp"} },
905     "output_path": "/tmp",
906     "priority": 1,
907     "runtime_constraints": {}
908 }`, nil, 0, func(t *TestDockerClient) {
909                 t.logWriter.Write(dockerLog(1, t.env[0][7:]+"\n"))
910                 t.logWriter.Close()
911         })
912
913         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
914         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
915         c.Check(strings.HasSuffix(api.Logs["stdout"].String(), "bilbo\n"), Equals, true)
916 }
917
918 type ArvMountCmdLine struct {
919         Cmd   []string
920         token string
921 }
922
923 func (am *ArvMountCmdLine) ArvMountTest(c []string, token string) (*exec.Cmd, error) {
924         am.Cmd = c
925         am.token = token
926         return nil, nil
927 }
928
929 func stubCert(temp string) string {
930         path := temp + "/ca-certificates.crt"
931         crt, _ := os.Create(path)
932         crt.Close()
933         arvadosclient.CertFiles = []string{path}
934         return path
935 }
936
937 func (s *TestSuite) TestSetupMounts(c *C) {
938         api := &ArvTestClient{}
939         kc := &KeepTestClient{}
940         cr := NewContainerRunner(api, kc, nil, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
941         am := &ArvMountCmdLine{}
942         cr.RunArvMount = am.ArvMountTest
943
944         realTemp, err := ioutil.TempDir("", "crunchrun_test1-")
945         c.Assert(err, IsNil)
946         certTemp, err := ioutil.TempDir("", "crunchrun_test2-")
947         c.Assert(err, IsNil)
948         stubCertPath := stubCert(certTemp)
949
950         defer os.RemoveAll(realTemp)
951         defer os.RemoveAll(certTemp)
952
953         i := 0
954         cr.MkTempDir = func(_ string, prefix string) (string, error) {
955                 i++
956                 d := fmt.Sprintf("%s/%s%d", realTemp, prefix, i)
957                 err := os.Mkdir(d, os.ModePerm)
958                 if err != nil && strings.Contains(err.Error(), ": file exists") {
959                         // Test case must have pre-populated the tempdir
960                         err = nil
961                 }
962                 return d, err
963         }
964
965         checkEmpty := func() {
966                 filepath.Walk(realTemp, func(path string, _ os.FileInfo, err error) error {
967                         c.Check(path, Equals, realTemp)
968                         c.Check(err, IsNil)
969                         return nil
970                 })
971         }
972
973         {
974                 i = 0
975                 cr.ArvMountPoint = ""
976                 cr.Container.Mounts = make(map[string]arvados.Mount)
977                 cr.Container.Mounts["/tmp"] = arvados.Mount{Kind: "tmp"}
978                 cr.OutputPath = "/tmp"
979
980                 err := cr.SetupMounts()
981                 c.Check(err, IsNil)
982                 c.Check(am.Cmd, DeepEquals, []string{"--foreground", "--allow-other", "--read-write", "--mount-by-pdh", "by_id", realTemp + "/keep1"})
983                 c.Check(cr.Binds, DeepEquals, []string{realTemp + "/2:/tmp"})
984                 cr.CleanupDirs()
985                 checkEmpty()
986         }
987
988         {
989                 i = 0
990                 cr.ArvMountPoint = ""
991                 cr.Container.Mounts = make(map[string]arvados.Mount)
992                 cr.Container.Mounts["/out"] = arvados.Mount{Kind: "tmp"}
993                 cr.Container.Mounts["/tmp"] = arvados.Mount{Kind: "tmp"}
994                 cr.OutputPath = "/out"
995
996                 err := cr.SetupMounts()
997                 c.Check(err, IsNil)
998                 c.Check(am.Cmd, DeepEquals, []string{"--foreground", "--allow-other", "--read-write", "--mount-by-pdh", "by_id", realTemp + "/keep1"})
999                 c.Check(cr.Binds, DeepEquals, []string{realTemp + "/2:/out", realTemp + "/3:/tmp"})
1000                 cr.CleanupDirs()
1001                 checkEmpty()
1002         }
1003
1004         {
1005                 i = 0
1006                 cr.ArvMountPoint = ""
1007                 cr.Container.Mounts = make(map[string]arvados.Mount)
1008                 cr.Container.Mounts["/tmp"] = arvados.Mount{Kind: "tmp"}
1009                 cr.OutputPath = "/tmp"
1010
1011                 apiflag := true
1012                 cr.Container.RuntimeConstraints.API = &apiflag
1013
1014                 err := cr.SetupMounts()
1015                 c.Check(err, IsNil)
1016                 c.Check(am.Cmd, DeepEquals, []string{"--foreground", "--allow-other", "--read-write", "--mount-by-pdh", "by_id", realTemp + "/keep1"})
1017                 c.Check(cr.Binds, DeepEquals, []string{realTemp + "/2:/tmp", stubCertPath + ":/etc/arvados/ca-certificates.crt:ro"})
1018                 cr.CleanupDirs()
1019                 checkEmpty()
1020
1021                 apiflag = false
1022         }
1023
1024         {
1025                 i = 0
1026                 cr.ArvMountPoint = ""
1027                 cr.Container.Mounts = map[string]arvados.Mount{
1028                         "/keeptmp": {Kind: "collection", Writable: true},
1029                 }
1030                 cr.OutputPath = "/keeptmp"
1031
1032                 os.MkdirAll(realTemp+"/keep1/tmp0", os.ModePerm)
1033
1034                 err := cr.SetupMounts()
1035                 c.Check(err, IsNil)
1036                 c.Check(am.Cmd, DeepEquals, []string{"--foreground", "--allow-other", "--read-write", "--mount-tmp", "tmp0", "--mount-by-pdh", "by_id", realTemp + "/keep1"})
1037                 c.Check(cr.Binds, DeepEquals, []string{realTemp + "/keep1/tmp0:/keeptmp"})
1038                 cr.CleanupDirs()
1039                 checkEmpty()
1040         }
1041
1042         {
1043                 i = 0
1044                 cr.ArvMountPoint = ""
1045                 cr.Container.Mounts = map[string]arvados.Mount{
1046                         "/keepinp": {Kind: "collection", PortableDataHash: "59389a8f9ee9d399be35462a0f92541c+53"},
1047                         "/keepout": {Kind: "collection", Writable: true},
1048                 }
1049                 cr.OutputPath = "/keepout"
1050
1051                 os.MkdirAll(realTemp+"/keep1/by_id/59389a8f9ee9d399be35462a0f92541c+53", os.ModePerm)
1052                 os.MkdirAll(realTemp+"/keep1/tmp0", os.ModePerm)
1053
1054                 err := cr.SetupMounts()
1055                 c.Check(err, IsNil)
1056                 c.Check(am.Cmd, DeepEquals, []string{"--foreground", "--allow-other", "--read-write", "--mount-tmp", "tmp0", "--mount-by-pdh", "by_id", realTemp + "/keep1"})
1057                 sort.StringSlice(cr.Binds).Sort()
1058                 c.Check(cr.Binds, DeepEquals, []string{realTemp + "/keep1/by_id/59389a8f9ee9d399be35462a0f92541c+53:/keepinp:ro",
1059                         realTemp + "/keep1/tmp0:/keepout"})
1060                 cr.CleanupDirs()
1061                 checkEmpty()
1062         }
1063
1064         {
1065                 i = 0
1066                 cr.ArvMountPoint = ""
1067                 cr.Container.RuntimeConstraints.KeepCacheRAM = 512
1068                 cr.Container.Mounts = map[string]arvados.Mount{
1069                         "/keepinp": {Kind: "collection", PortableDataHash: "59389a8f9ee9d399be35462a0f92541c+53"},
1070                         "/keepout": {Kind: "collection", Writable: true},
1071                 }
1072                 cr.OutputPath = "/keepout"
1073
1074                 os.MkdirAll(realTemp+"/keep1/by_id/59389a8f9ee9d399be35462a0f92541c+53", os.ModePerm)
1075                 os.MkdirAll(realTemp+"/keep1/tmp0", os.ModePerm)
1076
1077                 err := cr.SetupMounts()
1078                 c.Check(err, IsNil)
1079                 c.Check(am.Cmd, DeepEquals, []string{"--foreground", "--allow-other", "--read-write", "--file-cache", "512", "--mount-tmp", "tmp0", "--mount-by-pdh", "by_id", realTemp + "/keep1"})
1080                 sort.StringSlice(cr.Binds).Sort()
1081                 c.Check(cr.Binds, DeepEquals, []string{realTemp + "/keep1/by_id/59389a8f9ee9d399be35462a0f92541c+53:/keepinp:ro",
1082                         realTemp + "/keep1/tmp0:/keepout"})
1083                 cr.CleanupDirs()
1084                 checkEmpty()
1085         }
1086
1087         for _, test := range []struct {
1088                 in  interface{}
1089                 out string
1090         }{
1091                 {in: "foo", out: `"foo"`},
1092                 {in: nil, out: `null`},
1093                 {in: map[string]int{"foo": 123}, out: `{"foo":123}`},
1094         } {
1095                 i = 0
1096                 cr.ArvMountPoint = ""
1097                 cr.Container.Mounts = map[string]arvados.Mount{
1098                         "/mnt/test.json": {Kind: "json", Content: test.in},
1099                 }
1100                 err := cr.SetupMounts()
1101                 c.Check(err, IsNil)
1102                 sort.StringSlice(cr.Binds).Sort()
1103                 c.Check(cr.Binds, DeepEquals, []string{realTemp + "/2/mountdata.json:/mnt/test.json:ro"})
1104                 content, err := ioutil.ReadFile(realTemp + "/2/mountdata.json")
1105                 c.Check(err, IsNil)
1106                 c.Check(content, DeepEquals, []byte(test.out))
1107                 cr.CleanupDirs()
1108                 checkEmpty()
1109         }
1110
1111         // Read-only mount points are allowed underneath output_dir mount point
1112         {
1113                 i = 0
1114                 cr.ArvMountPoint = ""
1115                 cr.Container.Mounts = make(map[string]arvados.Mount)
1116                 cr.Container.Mounts = map[string]arvados.Mount{
1117                         "/tmp":     {Kind: "tmp"},
1118                         "/tmp/foo": {Kind: "collection"},
1119                 }
1120                 cr.OutputPath = "/tmp"
1121
1122                 os.MkdirAll(realTemp+"/keep1/tmp0", os.ModePerm)
1123
1124                 err := cr.SetupMounts()
1125                 c.Check(err, IsNil)
1126                 c.Check(am.Cmd, DeepEquals, []string{"--foreground", "--allow-other", "--read-write", "--file-cache", "512", "--mount-tmp", "tmp0", "--mount-by-pdh", "by_id", realTemp + "/keep1"})
1127                 c.Check(cr.Binds, DeepEquals, []string{realTemp + "/2:/tmp", realTemp + "/keep1/tmp0:/tmp/foo:ro"})
1128                 cr.CleanupDirs()
1129                 checkEmpty()
1130         }
1131
1132         // Writable mount points are not allowed underneath output_dir mount point
1133         {
1134                 i = 0
1135                 cr.ArvMountPoint = ""
1136                 cr.Container.Mounts = make(map[string]arvados.Mount)
1137                 cr.Container.Mounts = map[string]arvados.Mount{
1138                         "/tmp":     {Kind: "tmp"},
1139                         "/tmp/foo": {Kind: "collection", Writable: true},
1140                 }
1141                 cr.OutputPath = "/tmp"
1142
1143                 err := cr.SetupMounts()
1144                 c.Check(err, NotNil)
1145                 c.Check(err, ErrorMatches, `Writable mount points are not permitted underneath the output_path.*`)
1146                 cr.CleanupDirs()
1147                 checkEmpty()
1148         }
1149
1150         // Only mount points of kind 'collection' are allowed underneath output_dir mount point
1151         {
1152                 i = 0
1153                 cr.ArvMountPoint = ""
1154                 cr.Container.Mounts = make(map[string]arvados.Mount)
1155                 cr.Container.Mounts = map[string]arvados.Mount{
1156                         "/tmp":     {Kind: "tmp"},
1157                         "/tmp/foo": {Kind: "json"},
1158                 }
1159                 cr.OutputPath = "/tmp"
1160
1161                 err := cr.SetupMounts()
1162                 c.Check(err, NotNil)
1163                 c.Check(err, ErrorMatches, `Only mount points of kind 'collection' are supported underneath the output_path.*`)
1164                 cr.CleanupDirs()
1165                 checkEmpty()
1166         }
1167
1168         // Only mount point of kind 'collection' is allowed for stdin
1169         {
1170                 i = 0
1171                 cr.ArvMountPoint = ""
1172                 cr.Container.Mounts = make(map[string]arvados.Mount)
1173                 cr.Container.Mounts = map[string]arvados.Mount{
1174                         "stdin": {Kind: "tmp"},
1175                 }
1176
1177                 err := cr.SetupMounts()
1178                 c.Check(err, NotNil)
1179                 c.Check(err, ErrorMatches, `Unsupported mount kind 'tmp' for stdin.*`)
1180                 cr.CleanupDirs()
1181                 checkEmpty()
1182         }
1183 }
1184
1185 func (s *TestSuite) TestStdout(c *C) {
1186         helperRecord := `{
1187                 "command": ["/bin/sh", "-c", "echo $FROBIZ"],
1188                 "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
1189                 "cwd": "/bin",
1190                 "environment": {"FROBIZ": "bilbo"},
1191                 "mounts": {"/tmp": {"kind": "tmp"}, "stdout": {"kind": "file", "path": "/tmp/a/b/c.out"} },
1192                 "output_path": "/tmp",
1193                 "priority": 1,
1194                 "runtime_constraints": {}
1195         }`
1196
1197         api, _, _ := FullRunHelper(c, helperRecord, nil, 0, func(t *TestDockerClient) {
1198                 t.logWriter.Write(dockerLog(1, t.env[0][7:]+"\n"))
1199                 t.logWriter.Close()
1200         })
1201
1202         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
1203         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
1204         c.Check(api.CalledWith("collection.manifest_text", "./a/b 307372fa8fd5c146b22ae7a45b49bc31+6 0:6:c.out\n"), NotNil)
1205 }
1206
1207 // Used by the TestStdoutWithWrongPath*()
1208 func StdoutErrorRunHelper(c *C, record string, fn func(t *TestDockerClient)) (api *ArvTestClient, cr *ContainerRunner, err error) {
1209         rec := arvados.Container{}
1210         err = json.Unmarshal([]byte(record), &rec)
1211         c.Check(err, IsNil)
1212
1213         docker := NewTestDockerClient(0)
1214         docker.fn = fn
1215         docker.ImageRemove(nil, hwImageId, dockertypes.ImageRemoveOptions{})
1216
1217         api = &ArvTestClient{Container: rec}
1218         cr = NewContainerRunner(api, &KeepTestClient{}, docker, "zzzzz-zzzzz-zzzzzzzzzzzzzzz")
1219         am := &ArvMountCmdLine{}
1220         cr.RunArvMount = am.ArvMountTest
1221
1222         err = cr.Run()
1223         return
1224 }
1225
1226 func (s *TestSuite) TestStdoutWithWrongPath(c *C) {
1227         _, _, err := StdoutErrorRunHelper(c, `{
1228     "mounts": {"/tmp": {"kind": "tmp"}, "stdout": {"kind": "file", "path":"/tmpa.out"} },
1229     "output_path": "/tmp"
1230 }`, func(t *TestDockerClient) {})
1231
1232         c.Check(err, NotNil)
1233         c.Check(strings.Contains(err.Error(), "Stdout path does not start with OutputPath"), Equals, true)
1234 }
1235
1236 func (s *TestSuite) TestStdoutWithWrongKindTmp(c *C) {
1237         _, _, err := StdoutErrorRunHelper(c, `{
1238     "mounts": {"/tmp": {"kind": "tmp"}, "stdout": {"kind": "tmp", "path":"/tmp/a.out"} },
1239     "output_path": "/tmp"
1240 }`, func(t *TestDockerClient) {})
1241
1242         c.Check(err, NotNil)
1243         c.Check(strings.Contains(err.Error(), "Unsupported mount kind 'tmp' for stdout"), Equals, true)
1244 }
1245
1246 func (s *TestSuite) TestStdoutWithWrongKindCollection(c *C) {
1247         _, _, err := StdoutErrorRunHelper(c, `{
1248     "mounts": {"/tmp": {"kind": "tmp"}, "stdout": {"kind": "collection", "path":"/tmp/a.out"} },
1249     "output_path": "/tmp"
1250 }`, func(t *TestDockerClient) {})
1251
1252         c.Check(err, NotNil)
1253         c.Check(strings.Contains(err.Error(), "Unsupported mount kind 'collection' for stdout"), Equals, true)
1254 }
1255
1256 func (s *TestSuite) TestFullRunWithAPI(c *C) {
1257         os.Setenv("ARVADOS_API_HOST", "test.arvados.org")
1258         defer os.Unsetenv("ARVADOS_API_HOST")
1259         api, _, _ := FullRunHelper(c, `{
1260     "command": ["/bin/sh", "-c", "echo $ARVADOS_API_HOST"],
1261     "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
1262     "cwd": "/bin",
1263     "environment": {},
1264     "mounts": {"/tmp": {"kind": "tmp"} },
1265     "output_path": "/tmp",
1266     "priority": 1,
1267     "runtime_constraints": {"API": true}
1268 }`, nil, 0, func(t *TestDockerClient) {
1269                 t.logWriter.Write(dockerLog(1, t.env[1][17:]+"\n"))
1270                 t.logWriter.Close()
1271         })
1272
1273         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
1274         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
1275         c.Check(strings.HasSuffix(api.Logs["stdout"].String(), "test.arvados.org\n"), Equals, true)
1276         c.Check(api.CalledWith("container.output", "d41d8cd98f00b204e9800998ecf8427e+0"), NotNil)
1277 }
1278
1279 func (s *TestSuite) TestFullRunSetOutput(c *C) {
1280         os.Setenv("ARVADOS_API_HOST", "test.arvados.org")
1281         defer os.Unsetenv("ARVADOS_API_HOST")
1282         api, _, _ := FullRunHelper(c, `{
1283     "command": ["/bin/sh", "-c", "echo $ARVADOS_API_HOST"],
1284     "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
1285     "cwd": "/bin",
1286     "environment": {},
1287     "mounts": {"/tmp": {"kind": "tmp"} },
1288     "output_path": "/tmp",
1289     "priority": 1,
1290     "runtime_constraints": {"API": true}
1291 }`, nil, 0, func(t *TestDockerClient) {
1292                 t.api.Container.Output = "d4ab34d3d4f8a72f5c4973051ae69fab+122"
1293                 t.logWriter.Close()
1294         })
1295
1296         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
1297         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
1298         c.Check(api.CalledWith("container.output", "d4ab34d3d4f8a72f5c4973051ae69fab+122"), NotNil)
1299 }
1300
1301 func (s *TestSuite) TestStdoutWithExcludeFromOutputMountPointUnderOutputDir(c *C) {
1302         helperRecord := `{
1303                 "command": ["/bin/sh", "-c", "echo $FROBIZ"],
1304                 "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
1305                 "cwd": "/bin",
1306                 "environment": {"FROBIZ": "bilbo"},
1307                 "mounts": {
1308         "/tmp": {"kind": "tmp"},
1309         "/tmp/foo": {"kind": "collection",
1310                      "portable_data_hash": "a3e8f74c6f101eae01fa08bfb4e49b3a+54",
1311                      "exclude_from_output": true
1312         },
1313         "stdout": {"kind": "file", "path": "/tmp/a/b/c.out"}
1314     },
1315                 "output_path": "/tmp",
1316                 "priority": 1,
1317                 "runtime_constraints": {}
1318         }`
1319
1320         extraMounts := []string{"a3e8f74c6f101eae01fa08bfb4e49b3a+54"}
1321
1322         api, _, _ := FullRunHelper(c, helperRecord, extraMounts, 0, func(t *TestDockerClient) {
1323                 t.logWriter.Write(dockerLog(1, t.env[0][7:]+"\n"))
1324                 t.logWriter.Close()
1325         })
1326
1327         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
1328         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
1329         c.Check(api.CalledWith("collection.manifest_text", "./a/b 307372fa8fd5c146b22ae7a45b49bc31+6 0:6:c.out\n"), NotNil)
1330 }
1331
1332 func (s *TestSuite) TestStdoutWithMultipleMountPointsUnderOutputDir(c *C) {
1333         helperRecord := `{
1334                 "command": ["/bin/sh", "-c", "echo $FROBIZ"],
1335                 "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
1336                 "cwd": "/bin",
1337                 "environment": {"FROBIZ": "bilbo"},
1338                 "mounts": {
1339         "/tmp": {"kind": "tmp"},
1340         "/tmp/foo/bar": {"kind": "collection", "portable_data_hash": "a0def87f80dd594d4675809e83bd4f15+367", "path":"/file2_in_main.txt"},
1341         "/tmp/foo/sub1": {"kind": "collection", "portable_data_hash": "a0def87f80dd594d4675809e83bd4f15+367", "path":"/subdir1"},
1342         "/tmp/foo/sub1file2": {"kind": "collection", "portable_data_hash": "a0def87f80dd594d4675809e83bd4f15+367", "path":"/subdir1/file2_in_subdir1.txt"},
1343         "/tmp/foo/baz/sub2file2": {"kind": "collection", "portable_data_hash": "a0def87f80dd594d4675809e83bd4f15+367", "path":"/subdir1/subdir2/file2_in_subdir2.txt"},
1344         "stdout": {"kind": "file", "path": "/tmp/a/b/c.out"}
1345     },
1346                 "output_path": "/tmp",
1347                 "priority": 1,
1348                 "runtime_constraints": {}
1349         }`
1350
1351         extraMounts := []string{
1352                 "a0def87f80dd594d4675809e83bd4f15+367/file2_in_main.txt",
1353                 "a0def87f80dd594d4675809e83bd4f15+367/subdir1/file2_in_subdir1.txt",
1354                 "a0def87f80dd594d4675809e83bd4f15+367/subdir1/subdir2/file2_in_subdir2.txt",
1355         }
1356
1357         api, runner, realtemp := FullRunHelper(c, helperRecord, extraMounts, 0, func(t *TestDockerClient) {
1358                 t.logWriter.Write(dockerLog(1, t.env[0][7:]+"\n"))
1359                 t.logWriter.Close()
1360         })
1361
1362         c.Check(runner.Binds, DeepEquals, []string{realtemp + "/2:/tmp",
1363                 realtemp + "/keep1/by_id/a0def87f80dd594d4675809e83bd4f15+367/file2_in_main.txt:/tmp/foo/bar:ro",
1364                 realtemp + "/keep1/by_id/a0def87f80dd594d4675809e83bd4f15+367/subdir1/subdir2/file2_in_subdir2.txt:/tmp/foo/baz/sub2file2:ro",
1365                 realtemp + "/keep1/by_id/a0def87f80dd594d4675809e83bd4f15+367/subdir1:/tmp/foo/sub1:ro",
1366                 realtemp + "/keep1/by_id/a0def87f80dd594d4675809e83bd4f15+367/subdir1/file2_in_subdir1.txt:/tmp/foo/sub1file2:ro",
1367         })
1368
1369         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
1370         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
1371         for _, v := range api.Content {
1372                 if v["collection"] != nil {
1373                         c.Check(v["ensure_unique_name"], Equals, true)
1374                         collection := v["collection"].(arvadosclient.Dict)
1375                         if strings.Index(collection["name"].(string), "output") == 0 {
1376                                 manifest := collection["manifest_text"].(string)
1377
1378                                 c.Check(manifest, Equals, `./a/b 307372fa8fd5c146b22ae7a45b49bc31+6 0:6:c.out
1379 ./foo 3e426d509afffb85e06c4c96a7c15e91+27+Aa124ac75e5168396c73c0abcdefgh11234567890@569fa8c3 9:18:bar 9:18:sub1file2
1380 ./foo/baz 3e426d509afffb85e06c4c96a7c15e91+27+Aa124ac75e5168396c73c0bcdefghijk544332211@569fa8c5 9:18:sub2file2
1381 ./foo/sub1 3e426d509afffb85e06c4c96a7c15e91+27+Aa124ac75e5168396cabcdefghij6419876543234@569fa8c4 0:9:file1_in_subdir1.txt 9:18:file2_in_subdir1.txt
1382 ./foo/sub1/subdir2 3e426d509afffb85e06c4c96a7c15e91+27+Aa124ac75e5168396c73c0bcdefghijk544332211@569fa8c5 0:9:file1_in_subdir2.txt 9:18:file2_in_subdir2.txt
1383 `)
1384                         }
1385                 }
1386         }
1387 }
1388
1389 func (s *TestSuite) TestStdoutWithMountPointsUnderOutputDirDenormalizedManifest(c *C) {
1390         helperRecord := `{
1391                 "command": ["/bin/sh", "-c", "echo $FROBIZ"],
1392                 "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
1393                 "cwd": "/bin",
1394                 "environment": {"FROBIZ": "bilbo"},
1395                 "mounts": {
1396         "/tmp": {"kind": "tmp"},
1397         "/tmp/foo/bar": {"kind": "collection", "portable_data_hash": "b0def87f80dd594d4675809e83bd4f15+367/subdir1/file2_in_subdir1.txt"},
1398         "stdout": {"kind": "file", "path": "/tmp/a/b/c.out"}
1399     },
1400                 "output_path": "/tmp",
1401                 "priority": 1,
1402                 "runtime_constraints": {}
1403         }`
1404
1405         extraMounts := []string{
1406                 "b0def87f80dd594d4675809e83bd4f15+367/subdir1/file2_in_subdir1.txt",
1407         }
1408
1409         api, _, _ := FullRunHelper(c, helperRecord, extraMounts, 0, func(t *TestDockerClient) {
1410                 t.logWriter.Write(dockerLog(1, t.env[0][7:]+"\n"))
1411                 t.logWriter.Close()
1412         })
1413
1414         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
1415         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
1416         for _, v := range api.Content {
1417                 if v["collection"] != nil {
1418                         collection := v["collection"].(arvadosclient.Dict)
1419                         if strings.Index(collection["name"].(string), "output") == 0 {
1420                                 manifest := collection["manifest_text"].(string)
1421
1422                                 c.Check(manifest, Equals, `./a/b 307372fa8fd5c146b22ae7a45b49bc31+6 0:6:c.out
1423 ./foo 3e426d509afffb85e06c4c96a7c15e91+27+Aa124ac75e5168396c73c0abcdefgh11234567890@569fa8c3 10:17:bar
1424 `)
1425                         }
1426                 }
1427         }
1428 }
1429
1430 func (s *TestSuite) TestOutputSymlinkToInput(c *C) {
1431         helperRecord := `{
1432                 "command": ["/bin/sh", "-c", "echo $FROBIZ"],
1433                 "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
1434                 "cwd": "/bin",
1435                 "environment": {"FROBIZ": "bilbo"},
1436                 "mounts": {
1437         "/tmp": {"kind": "tmp"},
1438         "/keep/foo/sub1file2": {"kind": "collection", "portable_data_hash": "a0def87f80dd594d4675809e83bd4f15+367", "path": "/subdir1/file2_in_subdir1.txt"},
1439         "/keep/foo2": {"kind": "collection", "portable_data_hash": "a0def87f80dd594d4675809e83bd4f15+367"}
1440     },
1441                 "output_path": "/tmp",
1442                 "priority": 1,
1443                 "runtime_constraints": {}
1444         }`
1445
1446         extraMounts := []string{
1447                 "a0def87f80dd594d4675809e83bd4f15+367/subdir1/file2_in_subdir1.txt",
1448         }
1449
1450         api, _, _ := FullRunHelper(c, helperRecord, extraMounts, 0, func(t *TestDockerClient) {
1451                 log.Printf("realtemp is %v", t.realTemp)
1452                 os.Symlink("/keep/foo/sub1file2", t.realTemp+"/2/baz")
1453                 os.Symlink("/keep/foo2/subdir1/file2_in_subdir1.txt", t.realTemp+"/2/baz2")
1454                 os.Symlink("/keep/foo2/subdir1", t.realTemp+"/2/baz3")
1455                 os.Mkdir(t.realTemp+"/2/baz4", 0700)
1456                 os.Symlink("/keep/foo2/subdir1/file2_in_subdir1.txt", t.realTemp+"/2/baz4/baz5")
1457                 t.logWriter.Close()
1458         })
1459
1460         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
1461         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
1462         for _, v := range api.Content {
1463                 if v["collection"] != nil {
1464                         collection := v["collection"].(arvadosclient.Dict)
1465                         if strings.Index(collection["name"].(string), "output") == 0 {
1466                                 manifest := collection["manifest_text"].(string)
1467                                 c.Check(manifest, Equals, `. 3e426d509afffb85e06c4c96a7c15e91+27+Aa124ac75e5168396cabcdefghij6419876543234@569fa8c4 9:18:baz 9:18:baz2
1468 ./baz3 3e426d509afffb85e06c4c96a7c15e91+27+Aa124ac75e5168396cabcdefghij6419876543234@569fa8c4 0:9:file1_in_subdir1.txt 9:18:file2_in_subdir1.txt
1469 ./baz3/subdir2 3e426d509afffb85e06c4c96a7c15e91+27+Aa124ac75e5168396c73c0bcdefghijk544332211@569fa8c5 0:9:file1_in_subdir2.txt 9:18:file2_in_subdir2.txt
1470 ./baz4 3e426d509afffb85e06c4c96a7c15e91+27+Aa124ac75e5168396cabcdefghij6419876543234@569fa8c4 9:18:baz5
1471 `)
1472                         }
1473                 }
1474         }
1475 }
1476
1477 func (s *TestSuite) TestStdinCollectionMountPoint(c *C) {
1478         helperRecord := `{
1479                 "command": ["/bin/sh", "-c", "echo $FROBIZ"],
1480                 "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
1481                 "cwd": "/bin",
1482                 "environment": {"FROBIZ": "bilbo"},
1483                 "mounts": {
1484         "/tmp": {"kind": "tmp"},
1485         "stdin": {"kind": "collection", "portable_data_hash": "b0def87f80dd594d4675809e83bd4f15+367", "path": "/file1_in_main.txt"},
1486         "stdout": {"kind": "file", "path": "/tmp/a/b/c.out"}
1487     },
1488                 "output_path": "/tmp",
1489                 "priority": 1,
1490                 "runtime_constraints": {}
1491         }`
1492
1493         extraMounts := []string{
1494                 "b0def87f80dd594d4675809e83bd4f15+367/file1_in_main.txt",
1495         }
1496
1497         api, _, _ := FullRunHelper(c, helperRecord, extraMounts, 0, func(t *TestDockerClient) {
1498                 t.logWriter.Write(dockerLog(1, t.env[0][7:]+"\n"))
1499                 t.logWriter.Close()
1500         })
1501
1502         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
1503         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
1504         for _, v := range api.Content {
1505                 if v["collection"] != nil {
1506                         collection := v["collection"].(arvadosclient.Dict)
1507                         if strings.Index(collection["name"].(string), "output") == 0 {
1508                                 manifest := collection["manifest_text"].(string)
1509                                 c.Check(manifest, Equals, `./a/b 307372fa8fd5c146b22ae7a45b49bc31+6 0:6:c.out
1510 `)
1511                         }
1512                 }
1513         }
1514 }
1515
1516 func (s *TestSuite) TestStdinJsonMountPoint(c *C) {
1517         helperRecord := `{
1518                 "command": ["/bin/sh", "-c", "echo $FROBIZ"],
1519                 "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
1520                 "cwd": "/bin",
1521                 "environment": {"FROBIZ": "bilbo"},
1522                 "mounts": {
1523         "/tmp": {"kind": "tmp"},
1524         "stdin": {"kind": "json", "content": "foo"},
1525         "stdout": {"kind": "file", "path": "/tmp/a/b/c.out"}
1526     },
1527                 "output_path": "/tmp",
1528                 "priority": 1,
1529                 "runtime_constraints": {}
1530         }`
1531
1532         api, _, _ := FullRunHelper(c, helperRecord, nil, 0, func(t *TestDockerClient) {
1533                 t.logWriter.Write(dockerLog(1, t.env[0][7:]+"\n"))
1534                 t.logWriter.Close()
1535         })
1536
1537         c.Check(api.CalledWith("container.exit_code", 0), NotNil)
1538         c.Check(api.CalledWith("container.state", "Complete"), NotNil)
1539         for _, v := range api.Content {
1540                 if v["collection"] != nil {
1541                         collection := v["collection"].(arvadosclient.Dict)
1542                         if strings.Index(collection["name"].(string), "output") == 0 {
1543                                 manifest := collection["manifest_text"].(string)
1544                                 c.Check(manifest, Equals, `./a/b 307372fa8fd5c146b22ae7a45b49bc31+6 0:6:c.out
1545 `)
1546                         }
1547                 }
1548         }
1549 }
1550
1551 func (s *TestSuite) TestStderrMount(c *C) {
1552         api, _, _ := FullRunHelper(c, `{
1553     "command": ["/bin/sh", "-c", "echo hello;exit 1"],
1554     "container_image": "d4ab34d3d4f8a72f5c4973051ae69fab+122",
1555     "cwd": ".",
1556     "environment": {},
1557     "mounts": {"/tmp": {"kind": "tmp"},
1558                "stdout": {"kind": "file", "path": "/tmp/a/out.txt"},
1559                "stderr": {"kind": "file", "path": "/tmp/b/err.txt"}},
1560     "output_path": "/tmp",
1561     "priority": 1,
1562     "runtime_constraints": {}
1563 }`, nil, 1, func(t *TestDockerClient) {
1564                 t.logWriter.Write(dockerLog(1, "hello\n"))
1565                 t.logWriter.Write(dockerLog(2, "oops\n"))
1566                 t.logWriter.Close()
1567         })
1568
1569         final := api.CalledWith("container.state", "Complete")
1570         c.Assert(final, NotNil)
1571         c.Check(final["container"].(arvadosclient.Dict)["exit_code"], Equals, 1)
1572         c.Check(final["container"].(arvadosclient.Dict)["log"], NotNil)
1573
1574         c.Check(api.CalledWith("collection.manifest_text", "./a b1946ac92492d2347c6235b4d2611184+6 0:6:out.txt\n./b 38af5c54926b620264ab1501150cf189+5 0:5:err.txt\n"), NotNil)
1575 }