Merge branch 'master' into 14012-arvput-check-cache
[arvados.git] / sdk / python / tests / test_arv_put.py
index 346167846cd5ed185453ae85553a1676718e53d6..76144e8e38c07ee19c786a62b78494ebef4bf2b9 100644 (file)
@@ -12,16 +12,18 @@ import apiclient
 import datetime
 import hashlib
 import json
+import logging
 import mock
 import os
 import pwd
 import random
 import re
+import select
 import shutil
+import signal
 import subprocess
 import sys
 import tempfile
-import threading
 import time
 import unittest
 import uuid
@@ -547,7 +549,7 @@ class ArvadosExpectedBytesTest(ArvadosBaseTestCase):
                          writer.bytes_expected)
 
     def test_expected_bytes_for_device(self):
-        writer = arv_put.ArvPutUploadJob(['/dev/null'])
+        writer = arv_put.ArvPutUploadJob(['/dev/null'], use_cache=False, resume=False)
         self.assertIsNone(writer.bytes_expected)
         writer = arv_put.ArvPutUploadJob([__file__, '/dev/null'])
         self.assertIsNone(writer.bytes_expected)
@@ -574,6 +576,47 @@ class ArvadosPutReportTest(ArvadosBaseTestCase):
                                       arv_put.human_progress(count, None)))
 
 
+class ArvPutLogFormatterTest(ArvadosBaseTestCase):
+    matcher = r'\(X-Request-Id: req-[a-z0-9]{20}\)'
+
+    def setUp(self):
+        super(ArvPutLogFormatterTest, self).setUp()
+        self.stderr = tutil.StringIO()
+        self.loggingHandler = logging.StreamHandler(self.stderr)
+        self.loggingHandler.setFormatter(
+            arv_put.ArvPutLogFormatter(arvados.util.new_request_id()))
+        self.logger = logging.getLogger()
+        self.logger.addHandler(self.loggingHandler)
+        self.logger.setLevel(logging.DEBUG)
+
+    def tearDown(self):
+        self.logger.removeHandler(self.loggingHandler)
+        self.stderr.close()
+        self.stderr = None
+        super(ArvPutLogFormatterTest, self).tearDown()
+
+    def test_request_id_logged_only_once_on_error(self):
+        self.logger.error('Ooops, something bad happened.')
+        self.logger.error('Another bad thing just happened.')
+        log_lines = self.stderr.getvalue().split('\n')[:-1]
+        self.assertEqual(2, len(log_lines))
+        self.assertRegex(log_lines[0], self.matcher)
+        self.assertNotRegex(log_lines[1], self.matcher)
+
+    def test_request_id_logged_only_once_on_debug(self):
+        self.logger.debug('This is just a debug message.')
+        self.logger.debug('Another message, move along.')
+        log_lines = self.stderr.getvalue().split('\n')[:-1]
+        self.assertEqual(2, len(log_lines))
+        self.assertRegex(log_lines[0], self.matcher)
+        self.assertNotRegex(log_lines[1], self.matcher)
+
+    def test_request_id_not_logged_on_info(self):
+        self.logger.info('This should be a useful message')
+        log_lines = self.stderr.getvalue().split('\n')[:-1]
+        self.assertEqual(1, len(log_lines))
+        self.assertNotRegex(log_lines[0], self.matcher)
+
 class ArvadosPutTest(run_test_server.TestCaseWithServers,
                      ArvadosBaseTestCase,
                      tutil.VersionChecker):
@@ -581,8 +624,10 @@ class ArvadosPutTest(run_test_server.TestCaseWithServers,
     Z_UUID = 'zzzzz-zzzzz-zzzzzzzzzzzzzzz'
 
     def call_main_with_args(self, args):
-        self.main_stdout = tutil.StringIO()
-        self.main_stderr = tutil.StringIO()
+        self.main_stdout.seek(0, 0)
+        self.main_stdout.truncate(0)
+        self.main_stderr.seek(0, 0)
+        self.main_stderr.truncate(0)
         return arv_put.main(args, self.main_stdout, self.main_stderr)
 
     def call_main_on_test_file(self, args=[]):
@@ -598,8 +643,15 @@ class ArvadosPutTest(run_test_server.TestCaseWithServers,
         super(ArvadosPutTest, self).setUp()
         run_test_server.authorize_with('active')
         arv_put.api_client = None
+        self.main_stdout = tutil.StringIO()
+        self.main_stderr = tutil.StringIO()
+        self.loggingHandler = logging.StreamHandler(self.main_stderr)
+        self.loggingHandler.setFormatter(
+            arv_put.ArvPutLogFormatter(arvados.util.new_request_id()))
+        logging.getLogger().addHandler(self.loggingHandler)
 
     def tearDown(self):
+        logging.getLogger().removeHandler(self.loggingHandler)
         for outbuf in ['main_stdout', 'main_stderr']:
             if hasattr(self, outbuf):
                 getattr(self, outbuf).close()
@@ -678,6 +730,11 @@ class ArvadosPutTest(run_test_server.TestCaseWithServers,
                           self.call_main_with_args,
                           ['--project-uuid', self.Z_UUID, '--stream'])
 
+    def test_error_when_multiple_storage_classes_specified(self):
+        self.assertRaises(SystemExit,
+                          self.call_main_with_args,
+                          ['--storage-classes', 'hot,cold'])
+
     def test_error_when_excluding_absolute_path(self):
         tmpdir = self.make_tmpdir()
         self.assertRaises(SystemExit,
@@ -697,6 +754,18 @@ class ArvadosPutTest(run_test_server.TestCaseWithServers,
             self.assertLess(0, coll_save_mock.call_count)
             self.assertEqual("", self.main_stdout.getvalue())
 
+    def test_request_id_logging_on_error(self):
+        matcher = r'\(X-Request-Id: req-[a-z0-9]{20}\)\n'
+        coll_save_mock = mock.Mock(name='arv.collection.Collection().save_new()')
+        coll_save_mock.side_effect = arvados.errors.ApiError(
+            fake_httplib2_response(403), b'{}')
+        with mock.patch('arvados.collection.Collection.save_new',
+                        new=coll_save_mock):
+            with self.assertRaises(SystemExit) as exc_test:
+                self.call_main_with_args(['/dev/null'])
+            self.assertRegex(
+                self.main_stderr.getvalue(), matcher)
+
 
 class ArvPutIntegrationTest(run_test_server.TestCaseWithServers,
                             ArvadosBaseTestCase):
@@ -794,6 +863,30 @@ class ArvPutIntegrationTest(run_test_server.TestCaseWithServers,
         self.assertIn('4a9c8b735dce4b5fa3acf221a0b13628+11',
                       pipe.stdout.read().decode())
 
+    def test_sigint_logs_request_id(self):
+        # Start arv-put, give it a chance to start up, send SIGINT,
+        # and check that its output includes the X-Request-Id.
+        input_stream = subprocess.Popen(
+            ['sleep', '10'],
+            stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
+        pipe = subprocess.Popen(
+            [sys.executable, arv_put.__file__, '--stream'],
+            stdin=input_stream.stdout, stdout=subprocess.PIPE,
+            stderr=subprocess.STDOUT, env=self.ENVIRON)
+        # Wait for arv-put child process to print something (i.e., a
+        # log message) so we know its signal handler is installed.
+        select.select([pipe.stdout], [], [], 10)
+        pipe.send_signal(signal.SIGINT)
+        deadline = time.time() + 5
+        while (pipe.poll() is None) and (time.time() < deadline):
+            time.sleep(.1)
+        returncode = pipe.poll()
+        input_stream.terminate()
+        if returncode is None:
+            pipe.terminate()
+            self.fail("arv-put did not exit within 5 seconds")
+        self.assertRegex(pipe.stdout.read().decode(), r'\(X-Request-Id: req-[a-z0-9]{20}\)')
+
     def test_ArvPutSignedManifest(self):
         # ArvPutSignedManifest runs "arv-put foo" and then attempts to get
         # the newly created manifest from the API server, testing to confirm
@@ -881,12 +974,8 @@ class ArvPutIntegrationTest(run_test_server.TestCaseWithServers,
         (out, err) = p.communicate()
         self.assertRegex(
             err.decode(),
-            r'WARNING: Uploaded file .* access token expired, will re-upload it from scratch')
-        self.assertEqual(p.returncode, 0)
-        # Confirm that the resulting cache is different from the last run.
-        with open(cache_filepath, 'r') as c2:
-            new_cache = json.load(c2)
-        self.assertNotEqual(cache['manifest'], new_cache['manifest'])
+            r'ERROR: arv-put: Cache seems to contain invalid data.*')
+        self.assertEqual(p.returncode, 1)
 
     def test_put_collection_with_later_update(self):
         tmpdir = self.make_tmpdir()
@@ -973,6 +1062,18 @@ class ArvPutIntegrationTest(run_test_server.TestCaseWithServers,
                                        '--project-uuid', self.PROJECT_UUID])
         self.assertEqual(link_name, collection['name'])
 
+    def test_put_collection_with_storage_classes_specified(self):
+        collection = self.run_and_find_collection("", ['--storage-classes', 'hot'])
+
+        self.assertEqual(len(collection['storage_classes_desired']), 1)
+        self.assertEqual(collection['storage_classes_desired'][0], 'hot')
+
+    def test_put_collection_without_storage_classes_specified(self):
+        collection = self.run_and_find_collection("")
+
+        self.assertEqual(len(collection['storage_classes_desired']), 1)
+        self.assertEqual(collection['storage_classes_desired'][0], 'default')
+
     def test_exclude_filename_pattern(self):
         tmpdir = self.make_tmpdir()
         tmpsubdir = os.path.join(tmpdir, 'subdir')