Skip to content

Instantly share code, notes, and snippets.

@mschoch

mschoch/gist:354d0db2bf742f30509bd0bce37cb23a

Created March 21, 2018 18:50
Show Gist options
  • Save mschoch/354d0db2bf742f30509bd0bce37cb23a to your computer and use it in GitHub Desktop.
Save mschoch/354d0db2bf742f30509bd0bce37cb23a to your computer and use it in GitHub Desktop.
Download ZIP
Raw
gistfile1.txt
✗ ./testrunner -i cbft.ini cluster=D+F,get-cbcollect-info=True,GROUP=P0 -t fts.stable_topology_fts.StableTopFTS.test_match_consistency_error,update=True,consistency_level=at_plus,consistency_vectors="'{\"default_index_1\": {\"1\": 8}}'",GROUP=P0,cluster=D+F
Global Test input params:
{'cluster_name': 'cbft', 'ini': 'cbft.ini', 'num_nodes': 1}
Logs will be stored at /Users/mschoch/Documents/research/cbsource/testrunner/logs/testrunner-18-Mar-21_14-42-01/test_1
./testrunner -i cbft.ini -t fts.stable_topology_fts.StableTopFTS.test_match_consistency_error,update=True,consistency_level=at_plus,consistency_vectors='{"default_index_1": {"1": 8}}',GROUP=P0,cluster=D+F
Test Input params:
{'consistency_level': 'at_plus', 'GROUP': 'P0', 'update': 'True', 'consistency_vectors': '\'{"default_index_1": {"1": 8}}\'', 'num_nodes': 1, 'cluster_name': 'cbft', 'cluster': 'D+F', 'ini': 'cbft.ini', 'case_number': 1, 'logs_folder': '/Users/mschoch/Documents/research/cbsource/testrunner/logs/testrunner-18-Mar-21_14-42-01/test_1'}
Run before suite setup for fts.stable_topology_fts.StableTopFTS.test_match_consistency_error
test_match_consistency_error (fts.stable_topology_fts.StableTopFTS) ... 2018-03-21 14:42:01 | INFO | MainProcess | test_thread | [fts_base.setUp] ==== FTSbasetests setup is started for test #1 test_match_consistency_error ====
2018-03-21 14:42:01 | INFO | MainProcess | test_thread | [fts_base.cleanup_cluster] removing nodes from cluster ...
2018-03-21 14:42:01 | INFO | MainProcess | test_thread | [fts_base.cleanup_cluster] cleanup [ip:127.0.0.1 port:9000 ssh_username:root]
2018-03-21 14:42:01 | INFO | MainProcess | test_thread | [bucket_helper.delete_all_buckets_or_assert] deleting existing buckets [] on 127.0.0.1
2018-03-21 14:42:01 | INFO | MainProcess | test_thread | [bucket_helper.delete_all_buckets_or_assert] sleep 2 seconds to make sure all buckets were deleted completely.
2018-03-21 14:42:03 | INFO | MainProcess | test_thread | [cluster_helper.wait_for_ns_servers_or_assert] waiting for ns_server @ 127.0.0.1:9000
2018-03-21 14:42:03 | INFO | MainProcess | test_thread | [cluster_helper.wait_for_ns_servers_or_assert] ns_server @ 127.0.0.1:9000 is running
2018-03-21 14:42:03 | INFO | MainProcess | test_thread | [fts_base.cleanup_cluster] Removing user 'cbadminbucket'...
2018-03-21 14:42:03 | ERROR | MainProcess | test_thread | [rest_client._http_request] DELETE http://127.0.0.1:9000/settings/rbac/users/local/cbadminbucket body: headers: {'Content-Type': 'application/x-www-form-urlencoded', 'Accept': '*/*', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA==\n'} error: 404 reason: unknown "User was not found." auth: Administrator:password
2018-03-21 14:42:03 | INFO | MainProcess | test_thread | [fts_base.cleanup_cluster] "User was not found."
2018-03-21 14:42:03 | INFO | MainProcess | test_thread | [fts_base.init_cluster] Initializing Cluster ...
2018-03-21 14:42:04 | INFO | MainProcess | Cluster_Thread | [task.execute] server: ip:127.0.0.1 port:9000 ssh_username:root, nodes/self: {'ip': u'127.0.0.1', 'availableStorage': [], 'rest_username': '', 'id': u'[email protected]', 'uptime': u'17164', 'mcdMemoryReserved': 13107, 'storageTotalRam': 12795, 'hostname': u'127.0.0.1:9000', 'storage': [<membase.api.rest_client.NodeDataStorage object at 0x107c9efd0>], 'moxi': 12001, 'port': u'9000', 'version': u'5.5.0-0000-enterprise', 'memcached': 12000, 'status': u'healthy', 'clusterCompatibility': 327685, 'curr_items': 0, 'services': [u'eventing', u'fts', u'index', u'kv', u'n1ql'], 'rest_password': '', 'clusterMembership': u'active', 'memoryFree': 7590674432, 'memoryTotal': 17179869184, 'memoryQuota': 8738, 'mcdMemoryAllocated': 13107, 'os': u'x86_64-apple-darwin13.4.0', 'ports': []}
2018-03-21 14:42:04 | INFO | MainProcess | Cluster_Thread | [rest_client.init_cluster_memoryQuota] pools/default params : memoryQuota=8738
2018-03-21 14:42:04 | INFO | MainProcess | Cluster_Thread | [rest_client.set_indexer_storage_mode] settings/indexes params : storageMode=forestdb
2018-03-21 14:42:04 | ERROR | MainProcess | Cluster_Thread | [rest_client._http_request] POST http://127.0.0.1:9000/settings/indexes body: storageMode=forestdb headers: {'Content-Type': 'application/x-www-form-urlencoded', 'Accept': '*/*', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA==\n'} error: 400 reason: unknown {"errors":{"storageMode":"The value must be one of the following: [plasma,memory_optimized]"}} auth: Administrator:password
2018-03-21 14:42:04 | INFO | MainProcess | Cluster_Thread | [rest_client.init_cluster] settings/web params on 127.0.0.1:9000:username=Administrator&password=password&port=9000
2018-03-21 14:42:04 | ERROR | MainProcess | test_thread | [rest_client._http_request] DELETE http://127.0.0.1:9000/settings/rbac/users/local/cbadminbucket body: headers: {'Content-Type': 'application/x-www-form-urlencoded', 'Accept': '*/*', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA==\n'} error: 404 reason: unknown "User was not found." auth: Administrator:password
2018-03-21 14:42:04 | INFO | MainProcess | test_thread | [internal_user.delete_user] Exception while deleting user. Exception is -"User was not found."
2018-03-21 14:42:25 | INFO | MainProcess | Cluster_Thread | [rest_client.get_nodes_versions] Node versions in cluster [u'5.5.0-0000-enterprise']
2018-03-21 14:42:25 | INFO | MainProcess | Cluster_Thread | [rest_client.create_bucket] http://127.0.0.1:9000/pools/default/buckets with param: bucketType=membase&evictionPolicy=valueOnly&threadsNumber=3&ramQuotaMB=8238&authType=sasl&name=default&flushEnabled=1&replicaNumber=1&compressionMode=passive&saslPassword=None&replicaIndex=1
2018-03-21 14:42:25 | INFO | MainProcess | Cluster_Thread | [rest_client.create_bucket] 0.01 seconds to create bucket default
2018-03-21 14:42:25 | INFO | MainProcess | Cluster_Thread | [bucket_helper.wait_for_memcached] waiting for memcached bucket : default in 127.0.0.1 to accept set ops
2018-03-21 14:42:27 | INFO | MainProcess | Cluster_Thread | [data_helper.direct_client] creating direct client 127.0.0.1:12000 default
2018-03-21 14:42:27 | INFO | MainProcess | Cluster_Thread | [data_helper.direct_client] creating direct client 127.0.0.1:12000 default
2018-03-21 14:42:27 | INFO | MainProcess | Cluster_Thread | [task.check] bucket 'default' was created with per node RAM quota: 8238
2018-03-21 14:42:28 | INFO | MainProcess | test_thread | [rest_client.diag_eval] /diag/eval status on 127.0.0.1:9000: True content: "/Users/mschoch/Documents/research/cbsource/ns_server/logs/n_0" command: filename:absname(element(2, application:get_env(ns_server,error_logger_mf_dir))).
2018-03-21 14:42:28 | INFO | MainProcess | test_thread | [remote_util.__init__] connecting to 127.0.0.1 with username:root password:couchbase ssh_key:
2018-03-21 14:42:28 | INFO | MainProcess | test_thread | [remote_util.__init__] Connected to 127.0.0.1
2018-03-21 14:42:28 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] running command.raw on 127.0.0.1: /sbin/sysctl -n machdep.cpu.brand_string
2018-03-21 14:42:28 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] command executed successfully
2018-03-21 14:42:28 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] running command.raw on 127.0.0.1: zgrep "panic:" "/Users/mschoch/Documents/research/cbsource/ns_server/logs/n_0"/fts.log* | wc -l
2018-03-21 14:42:28 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] command executed successfully
2018-03-21 14:42:28 | INFO | MainProcess | test_thread | [fts_base.check_error_count_in_fts_log] 0
2018-03-21 14:42:28 | INFO | MainProcess | test_thread | [fts_base.__initialize_error_count_dict] {'127.0.0.1': {'panic:': 0}}
2018-03-21 14:42:28 | INFO | MainProcess | test_thread | [fts_base.setUp] ==== FTSbasetests setup is finished for test #1 test_match_consistency_error ====
2018-03-21 14:42:28 | INFO | MainProcess | test_thread | [data_helper.direct_client] creating direct client 127.0.0.1:12000 default
2018-03-21 14:42:29 | INFO | Process-2 | load_gen_task | [data_helper.direct_client] creating direct client 127.0.0.1:12000 default
2018-03-21 14:42:29 | INFO | Process-4 | load_gen_task | [data_helper.direct_client] creating direct client 127.0.0.1:12000 default
2018-03-21 14:42:29 | INFO | Process-3 | load_gen_task | [data_helper.direct_client] creating direct client 127.0.0.1:12000 default
2018-03-21 14:42:29 | INFO | Process-5 | load_gen_task | [data_helper.direct_client] creating direct client 127.0.0.1:12000 default
2018-03-21 14:42:29 | INFO | MainProcess | test_thread | [fts_base.load_data] Loading phase complete!
2018-03-21 14:42:29 | INFO | MainProcess | test_thread | [rest_client.fetch_bucket_stats] http://127.0.0.1:9000/pools/default/buckets/default/stats?zoom=minute
2018-03-21 14:42:29 | INFO | MainProcess | test_thread | [rest_client.fetch_bucket_stats] http://127.0.0.1:9000/pools/default/buckets/default/stats?zoom=minute
2018-03-21 14:42:29 | INFO | MainProcess | test_thread | [rest_client.fetch_bucket_stats] http://127.0.0.1:9000/pools/default/buckets/default/stats?zoom=minute
2018-03-21 14:42:29 | INFO | MainProcess | test_thread | [fts_base.wait_till_items_in_bucket_equal] Docs in bucket default = 0
2018-03-21 14:42:29 | INFO | MainProcess | test_thread | [fts_base.sleep] sleep for 1 secs. sleeping 1s to allow for item loading ...
2018-03-21 14:42:30 | INFO | MainProcess | test_thread | [rest_client.fetch_bucket_stats] http://127.0.0.1:9000/pools/default/buckets/default/stats?zoom=minute
2018-03-21 14:42:30 | INFO | MainProcess | test_thread | [fts_base.create] Checking if index already exists ...
2018-03-21 14:42:30 | ERROR | MainProcess | test_thread | [rest_client._http_request] GET http://127.0.0.1:9200/api/index/default_index_1 body: headers: {'Content-Type': 'application/json', 'Accept': '*/*', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA==\n'} error: 400 reason: rest_auth: preparePerms, err: index not found {"error":"rest_auth: preparePerms, err: index not found","req":"\u0026http.Request{Method:\"GET\", URL:(*url.URL)(0xc42be18a80), Proto:\"HTTP/1.1\", ProtoMajor:1, ProtoMinor:1, Header:http.Header{\"Authorization\":[]string{\"Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA==\"}, \"Accept\":[]string{\"*/*\"}, \"User-Agent\":[]string{\"Python-httplib2/$Rev: 259 $\"}, \"Content-Length\":[]string{\"0\"}, \"Accept-Encoding\":[]string{\"compress, gzip\"}, \"Content-Type\":[]string{\"application/json\"}}, Body:http.noBody{}, GetBody:(func() (io.ReadCloser, error))(nil), ContentLength:0, TransferEncoding:[]string(nil), Close:false, Host:\"127.0.0.1:9200\", Form:url.Values(nil), PostForm:url.Values(nil), MultipartForm:(*multipart.Form)(nil), Trailer:http.Header(nil), RemoteAddr:\"127.0.0.1:63761\", RequestURI:\"/api/index/default_index_1\", TLS:(*tls.ConnectionState)(nil), Cancel:(\u003c-chan struct {})(nil), Response:(*http.Response)(nil), ctx:(*context.valueCtx)(0xc42f7aaf00)}","status":"fail"} auth: Administrator:password
2018-03-21 14:42:30 | ERROR | MainProcess | test_thread | [rest_client._http_request] DELETE http://127.0.0.1:9200/api/index/default_index_1 body: headers: {'Content-Type': 'application/json', 'Accept': '*/*', 'Authorization': 'Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA==\n'} error: 400 reason: rest_auth: preparePerms, err: index not found {"error":"rest_auth: preparePerms, err: index not found","req":"\u0026http.Request{Method:\"DELETE\", URL:(*url.URL)(0xc42be18c00), Proto:\"HTTP/1.1\", ProtoMajor:1, ProtoMinor:1, Header:http.Header{\"Accept-Encoding\":[]string{\"identity\"}, \"Content-Length\":[]string{\"0\"}, \"Content-Type\":[]string{\"application/json\"}, \"Authorization\":[]string{\"Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA==\"}, \"Accept\":[]string{\"*/*\"}, \"User-Agent\":[]string{\"Python-httplib2/$Rev: 259 $\"}}, Body:http.noBody{}, GetBody:(func() (io.ReadCloser, error))(nil), ContentLength:0, TransferEncoding:[]string(nil), Close:false, Host:\"127.0.0.1:9200\", Form:url.Values(nil), PostForm:url.Values(nil), MultipartForm:(*multipart.Form)(nil), Trailer:http.Header(nil), RemoteAddr:\"127.0.0.1:63762\", RequestURI:\"/api/index/default_index_1\", TLS:(*tls.ConnectionState)(nil), Cancel:(\u003c-chan struct {})(nil), Response:(*http.Response)(nil), ctx:(*context.valueCtx)(0xc42f7ab0e0)}","status":"fail"} auth: Administrator:password
2018-03-21 14:42:30 | INFO | MainProcess | test_thread | [fts_base.create] Creating fulltext-index default_index_1 on 127.0.0.1
2018-03-21 14:42:30 | INFO | MainProcess | test_thread | [rest_client.create_fts_index] {"params": {"store": {"mossStoreOptions": {}, "kvStoreName": "mossStore"}}, "name": "default_index_1", "planParams": {"numReplicas": 0, "maxPartitionsPerPIndex": 171}, "sourceName": "default", "sourceUUID": "", "sourceType": "couchbase", "type": "fulltext-index", "uuid": ""}
2018-03-21 14:42:30 | INFO | MainProcess | test_thread | [rest_client.create_fts_index] Index default_index_1 created
2018-03-21 14:42:30 | INFO | MainProcess | test_thread | [fts_base.is_index_partitioned_balanced] Validating index distribution for default_index_1 ...
2018-03-21 14:42:30 | INFO | MainProcess | test_thread | [fts_base.sleep] sleep for 5 secs. No pindexes found, waiting for index to get created ...
2018-03-21 14:42:35 | INFO | MainProcess | test_thread | [fts_base.is_index_partitioned_balanced] Validated: Number of PIndexes = 6
2018-03-21 14:42:35 | INFO | MainProcess | test_thread | [fts_base.is_index_partitioned_balanced] Validated: Every pIndex serves 171 partitions or lesser
2018-03-21 14:42:35 | INFO | MainProcess | test_thread | [fts_base.is_index_partitioned_balanced] Expecting num of partitions in each node in range 853-1024
2018-03-21 14:42:35 | INFO | MainProcess | test_thread | [fts_base.is_index_partitioned_balanced] Validated: Node 1c4194ca934918b220d85a012784561b houses 6 pindexes which serve 1024 partitions
2018-03-21 14:42:35 | INFO | MainProcess | test_thread | [rest_client.fetch_bucket_stats] http://127.0.0.1:9000/pools/default/buckets/default/stats?zoom=minute
2018-03-21 14:42:35 | INFO | MainProcess | test_thread | [fts_base.wait_for_indexing_complete] Docs in bucket = 1000, docs in FTS index 'default_index_1': 1000
2018-03-21 14:42:35 | INFO | MainProcess | test_thread | [rest_client.fetch_bucket_stats] http://127.0.0.1:9000/pools/default/buckets/default/stats?zoom=minute
2018-03-21 14:42:35 | INFO | MainProcess | test_thread | [fts_base.validate_index_count] Docs in index default_index_1=1000, bucket docs=1000
2018-03-21 14:42:35 | INFO | MainProcess | test_thread | [fts_base.async_perform_update_delete] Updating keys @ C1 with expiry=0
2018-03-21 14:42:36 | INFO | MainProcess | test_thread | [data_helper.direct_client] creating direct client 127.0.0.1:12000 default
2018-03-21 14:42:37 | INFO | MainProcess | test_thread | [fts_base.async_perform_update_delete] Batched updates loaded to cluster(s)
2018-03-21 14:42:37 | INFO | MainProcess | test_thread | [fts_base.sleep] sleep for 60 secs. Waiting for updates to get indexed... ...
2018-03-21 14:43:37 | INFO | MainProcess | test_thread | [rest_client.fetch_bucket_stats] http://127.0.0.1:9000/pools/default/buckets/default/stats?zoom=minute
2018-03-21 14:43:37 | INFO | MainProcess | test_thread | [fts_base.wait_for_indexing_complete] Docs in bucket = 1000, docs in FTS index 'default_index_1': 1000
2018-03-21 14:43:37 | INFO | MainProcess | test_thread | [rest_client.fetch_bucket_stats] http://127.0.0.1:9000/pools/default/buckets/default/stats?zoom=minute
2018-03-21 14:43:37 | INFO | MainProcess | test_thread | [fts_base.validate_index_count] Docs in index default_index_1=1000, bucket docs=1000
2018-03-21 14:43:37 | INFO | MainProcess | test_thread | [fts_base.run_fts_query] Running query {"indexName": "default_index_1", "from": 0, "fields": [], "explain": false, "ctl": {"timeout": 60000, "consistency": {"vectors": {"default_index_1": {"1": 8}}, "level": "at_plus"}}, "query": {"match_all": {}}, "size": 10000000} on node: 127.0.0.1:9200
2018-03-21 14:45:37 | ERROR | MainProcess | test_thread | [fts_base.execute_query] Error running query: ''
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [stable_topology_fts.test_match_consistency_error] Hits: -1
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.__init__] connecting to 127.0.0.1 with username:root password:couchbase ssh_key:
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.__init__] Connected to 127.0.0.1
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] running command.raw on 127.0.0.1: /sbin/sysctl -n machdep.cpu.brand_string
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] command executed successfully
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] running command.raw on 127.0.0.1: ls /Applications/Couchbase\ Server.app/Contents/Resources/couchbase-core/VERSION.txt
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] command executed successfully
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] /
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] A
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] p
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] p
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] l
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] i
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] c
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] a
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] t
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] i
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] o
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] n
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] s
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] /
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] C
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] o
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] u
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] c
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] h
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] b
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] a
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] s
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output]
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] S
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] r
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] v
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] r
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] .
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] a
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] p
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] p
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] /
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] C
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] o
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] n
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] t
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] n
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] t
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] s
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] /
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] R
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] s
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] o
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] u
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] r
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] c
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] s
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] /
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] c
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] o
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] u
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] c
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] h
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] b
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] a
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] s
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] -
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] c
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] o
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] r
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] /
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] V
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] E
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] R
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] S
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] I
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] O
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] N
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] .
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] t
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] x
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] t
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output]
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.__init__] connecting to 127.0.0.1 with username:root password:couchbase ssh_key:
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.__init__] Connected to 127.0.0.1
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] running command.raw on 127.0.0.1: /sbin/sysctl -n machdep.cpu.brand_string
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] command executed successfully
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] running command.raw on 127.0.0.1: ls /Applications/Couchbase\ Server.app/Contents/Resources/couchbase-core/VERSION.txt
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] command executed successfully
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] /
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] A
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] p
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] p
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] l
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] i
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] c
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] a
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] t
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] i
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] o
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] n
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] s
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] /
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] C
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] o
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] u
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] c
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] h
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] b
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] a
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] s
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output]
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] S
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] r
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] v
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] r
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] .
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] a
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] p
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] p
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] /
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] C
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] o
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] n
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] t
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] n
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] t
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] s
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] /
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] R
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] s
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] o
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] u
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] r
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] c
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] s
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] /
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] c
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] o
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] u
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] c
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] h
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] b
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] a
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] s
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] -
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] c
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] o
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] r
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] e
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] /
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] V
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] E
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] R
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] S
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] I
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] O
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] N
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] .
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] t
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] x
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output] t
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.log_command_output]
ERROR
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [rest_client.diag_eval] /diag/eval status on 127.0.0.1:9000: True content: "/Users/mschoch/Documents/research/cbsource/ns_server/logs/n_0" command: filename:absname(element(2, application:get_env(ns_server,error_logger_mf_dir))).
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.__init__] connecting to 127.0.0.1 with username:root password:couchbase ssh_key:
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.__init__] Connected to 127.0.0.1
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] running command.raw on 127.0.0.1: /sbin/sysctl -n machdep.cpu.brand_string
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] command executed successfully
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] running command.raw on 127.0.0.1: zgrep "panic:" "/Users/mschoch/Documents/research/cbsource/ns_server/logs/n_0"/fts.log* | wc -l
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] command executed successfully
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [fts_base.check_error_count_in_fts_log] 0
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [fts_base.check_error_count_in_fts_log] Initial 'panic:' count on 127.0.0.1 :0, now :0
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [fts_base.tearDown] ==== FTSbasetests cleanup is started for test #1 test_match_consistency_error ====
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [fts_base.delete] Deleting fulltext-index default_index_1 on 127.0.0.1
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.__init__] connecting to 127.0.0.1 with username:root password:couchbase ssh_key:
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.__init__] Connected to 127.0.0.1
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] running command.raw on 127.0.0.1: /sbin/sysctl -n machdep.cpu.brand_string
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] command executed successfully
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] running command.raw on 127.0.0.1: ls /Users/mschoch/Documents/research/cbsource/ns_server/data/n_0/data/@fts |grep ^default_index_1 | wc -l
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] command executed successfully
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [fts_base.are_index_files_deleted_from_disk] 2
2018-03-21 14:45:37 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] running command.raw on 127.0.0.1: ls /Users/mschoch/Documents/research/cbsource/ns_server/data/n_0/data/@fts |grep ^default_index_1 | wc -l
2018-03-21 14:45:38 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] command executed successfully
2018-03-21 14:45:38 | INFO | MainProcess | test_thread | [fts_base.are_index_files_deleted_from_disk] 1
2018-03-21 14:45:38 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] running command.raw on 127.0.0.1: ls /Users/mschoch/Documents/research/cbsource/ns_server/data/n_0/data/@fts |grep ^default_index_1 | wc -l
2018-03-21 14:45:38 | INFO | MainProcess | test_thread | [remote_util.execute_command_raw] command executed successfully
2018-03-21 14:45:38 | INFO | MainProcess | test_thread | [fts_base.are_index_files_deleted_from_disk] 0
2018-03-21 14:45:38 | INFO | MainProcess | test_thread | [fts_base.delete] Validated: all index files for default_index_1 deleted from disk
2018-03-21 14:45:38 | INFO | MainProcess | test_thread | [fts_base.cleanup_cluster] removing nodes from cluster ...
2018-03-21 14:45:38 | INFO | MainProcess | test_thread | [fts_base.cleanup_cluster] cleanup [ip:127.0.0.1 port:9000 ssh_username:root]
2018-03-21 14:45:38 | INFO | MainProcess | test_thread | [bucket_helper.delete_all_buckets_or_assert] deleting existing buckets [u'default'] on 127.0.0.1
2018-03-21 14:45:38 | INFO | MainProcess | test_thread | [bucket_helper.delete_all_buckets_or_assert] remove bucket default ...
2018-03-21 14:45:39 | INFO | MainProcess | test_thread | [bucket_helper.delete_all_buckets_or_assert] deleted bucket : default from 127.0.0.1
2018-03-21 14:45:39 | INFO | MainProcess | test_thread | [bucket_helper.wait_for_bucket_deletion] waiting for bucket deletion to complete....
2018-03-21 14:45:39 | INFO | MainProcess | test_thread | [rest_client.bucket_exists] node 127.0.0.1 existing buckets : []
2018-03-21 14:45:39 | INFO | MainProcess | test_thread | [bucket_helper.delete_all_buckets_or_assert] sleep 2 seconds to make sure all buckets were deleted completely.
2018-03-21 14:45:41 | INFO | MainProcess | test_thread | [cluster_helper.wait_for_ns_servers_or_assert] waiting for ns_server @ 127.0.0.1:9000
2018-03-21 14:45:41 | INFO | MainProcess | test_thread | [cluster_helper.wait_for_ns_servers_or_assert] ns_server @ 127.0.0.1:9000 is running
Cluster instance shutdown with force
2018-03-21 14:45:41 | INFO | MainProcess | test_thread | [fts_base.cleanup_cluster] Removing user 'cbadminbucket'...
2018-03-21 14:45:41 | INFO | MainProcess | test_thread | [fts_base.tearDown] ==== FTSbasetests cleanup is finished for test #1 test_match_consistency_error ===
Cluster instance shutdown with force
======================================================================
ERROR: test_match_consistency_error (fts.stable_topology_fts.StableTopFTS)
----------------------------------------------------------------------
Traceback (most recent call last):
File "pytests/fts/stable_topology_fts.py", line 174, in test_match_consistency_error
shell.start_server()
File "lib/remote/remote_util.py", line 440, in start_server
fv, sv, bn = self.get_cbversion("linux")
File "lib/remote/remote_util.py", line 4455, in get_cbversion
if self.file_exists(LINUX_CB_PATH, VERSION_FILE):
File "lib/remote/remote_util.py", line 1195, in file_exists
sftp = self._ssh_client.open_sftp()
File "build/bdist.macosx-10.10-intel/egg/paramiko/client.py", line 439, in open_sftp
return self._transport.open_sftp_client()
AttributeError: 'NoneType' object has no attribute 'open_sftp_client'
----------------------------------------------------------------------
Ran 1 test in 219.428s
FAILED (errors=1)
summary so far suite fts.stable_topology_fts.StableTopFTS , pass 0 , fail 1
failures so far...
fts.stable_topology_fts.StableTopFTS.test_match_consistency_error
testrunner logs, diags and results are available under /Users/mschoch/Documents/research/cbsource/testrunner/logs/testrunner-18-Mar-21_14-42-01/test_1
Run after suite setup for fts.stable_topology_fts.StableTopFTS.test_match_consistency_error
Thread Cluster_Thread was not properly terminated, will be terminated now.
Thread Cluster_Thread was not properly terminated, will be terminated now.
Exception OSError: OSError(3, 'No such process') in <Finalize object, dead> ignored
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment