search

noobaa / noobaa-core

High-performance S3 application gateway to any backend - file / s3-compatible / multi-clouds / caching / replication ...
https://www.noobaa.io
Apache License 2.0
265 stars 78 forks source link

NS-CACHE: Read small object ends up with 2 object_mds in cache bucket (1 deleted, 1 alive) #6186

Closed guymguym closed 3 days ago

guymguym commented 3 years ago

Environment info

Actual behavior

  1. Read small object (<4K) from cache bucket completed but with two object_mds added to the DB - one is deleted and the other is alive.
  2. Also this error is in the endpoint logs - see full log below 
    E11000 duplicate key error collection: nbcore.objectmds index: latest_version_index dup key

Expected behavior

  1. A simple get operation should not create two objectmds, and no log errors.

Steps to reproduce

alias s3='AWS_ACCESS_KEY_ID=xxx AWS_SECRET_ACCESS_KEY=yyy aws --endpoint http://192.168.64.132:30798 s3'
# upload to hub-local
s3 cp --recursive pkg s3://hub-local/pkg
# read one object from hub-local-cache 
s3 cp s3://hub-local-cache/pkg/version/version.go -
# succeeds

Check the DB items - the first is the hub-local one:

> db.objectmds.find({key:"pkg/version/version.go"}).pretty()
{
    "_id" : ObjectId("5f6b6ed91b2790000ccff514"),
    "system" : ObjectId("5f6b6380b1bc730028bc6e02"),
    "bucket" : ObjectId("5f6b6dd4b485a80028fba475"),
    "key" : "pkg/version/version.go",
    "content_type" : "application/octet-stream",
    "size" : 644,
    "md5_b64" : "JQIiACalUt0TFLs87CcSxg==",
    "xattr" : {

    },
    "create_time" : ISODate("2020-09-23T15:50:49.445Z"),
    "etag" : "2502220026a552dd1314bb3cec2712c6",
    "num_parts" : 1,
    "version_seq" : 60,
    "stats" : {
        "last_read" : ISODate("2020-09-24T11:55:59.803Z"),
        "reads" : 14
    }
}
{
    "_id" : ObjectId("5f6c894fdcd2ee000c58ff26"),
    "system" : ObjectId("5f6b6380b1bc730028bc6e02"),
    "bucket" : ObjectId("5f6c891cf28864002de18eb2"),
    "key" : "pkg/version/version.go",
    "content_type" : "application/octet-stream",
    "upload_size" : 0,
    "upload_started" : ObjectId("5f6c894fdcd2ee000c58ff26"),
    "cache_last_valid_time" : ISODate("2020-09-24T11:55:59.744Z"),
    "size" : 644,
    "xattr" : {
        "noobaa-namespace-s3-bucket" : "hub-local"
    },
    "deleted" : ISODate("2020-09-24T11:55:59.999Z"),
    "reclaimed" : ISODate("2020-09-24T11:56:29.662Z")
}
{
    "_id" : ObjectId("5f6c894fdcd2ee000c58ff28"),
    "system" : ObjectId("5f6b6380b1bc730028bc6e02"),
    "bucket" : ObjectId("5f6c891cf28864002de18eb2"),
    "key" : "pkg/version/version.go",
    "content_type" : "application/octet-stream",
    "cache_last_valid_time" : ISODate("2020-09-24T11:55:59.974Z"),
    "size" : 644,
    "xattr" : {
        "noobaa-namespace-s3-bucket" : "hub-local"
    },
    "create_time" : ISODate("2020-09-24T11:55:59.974Z"),
    "etag" : "2502220026a552dd1314bb3cec2712c6",
    "last_modified_time" : ISODate("2020-09-23T15:50:49Z"),
    "md5_b64" : "JQIiACalUt0TFLs87CcSxg==",
    "num_parts" : 1,
    "version_seq" : 61
}

More information - Screenshots / Logs / Other output

Endpoint logs:

Sep-24 11:55:59.717 [Endpoint/12]    [L0] core.util.signature_utils:: _string_to_sign_v4 method HEAD pathname /hub-local-cache/pkg/version/version.go search  headers { Host: '192.168.64.132:30798', 'Accept-Encoding': 'identity', 'User-Agent': 'aws-cli/2.0.50 Python/3.8.5 Darwin/19.6.0 source/x86_64 command/s3.cp', 'X-Amz-Date': '20200924T115559Z', 'X-Amz-Content-Sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855', Authorization: 'AWS4-HMAC-SHA256 Credential=1EPzXy87z72a2UAVbfya/20200924/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=18814529ded64dfee69c0191f6f30018e808b7eecb6fb005dba897be20dcc2ee' } region us-east-1 canonical_str
HEAD
/hub-local-cache/pkg/version/version.go

host:192.168.64.132:30798
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20200924T115559Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
 string_to_sign
AWS4-HMAC-SHA256
20200924T115559Z
20200924/us-east-1/s3/aws4_request
3bfefd66ea747b063a091013fff0a7279584f83441916862570ff48a3d6516c5

Sep-24 11:55:59.717 [Endpoint/12]    [L0] core.endpoint.s3.s3_rest:: S3 REQUEST HEAD /hub-local-cache/pkg/version/version.go op head_object request_id kfgrfqlg-auuopb-am4 { host: '192.168.64.132:30798', 'accept-encoding': 'identity', 'user-agent': 'aws-cli/2.0.50 Python/3.8.5 Darwin/19.6.0 source/x86_64 command/s3.cp', 'x-amz-date': '20200924T115559Z', 'x-amz-content-sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855', authorization: 'AWS4-HMAC-SHA256 Credential=1EPzXy87z72a2UAVbfya/20200924/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=18814529ded64dfee69c0191f6f30018e808b7eecb6fb005dba897be20dcc2ee' }
Sep-24 11:55:59.718 [Endpoint/12]    [L0] core.server.object_services.object_server:: object_server.read_object_md: { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', version_id: undefined, md_conditions: undefined, encryption: undefined }
Sep-24 11:55:59.720 [Endpoint/12] [ERROR] CONSOLE:: RPC._on_request: ERROR srv object_api.read_object_md reqid 2605@fcall://fcall(7quzig5t) connid fcall://fcall(7quzig5t) Error: No such object: obj_id undefined bucket SENSITIVE-b8656b72c3595164 key pkg/version/version.go
    at check_object_mode (/root/node_modules/noobaa-core/src/server/object_services/object_server.js:1491:15)
    at find_object_md (/root/node_modules/noobaa-core/src/server/object_services/object_server.js:1413:5)
    at async Object.read_object_md (/root/node_modules/noobaa-core/src/server/object_services/object_server.js:771:17)
Sep-24 11:55:59.721 [Endpoint/12]    [L0] core.sdk.namespace_cache:: NamespaceCache.read_object_md: error in cache RpcError: No such object: obj_id undefined bucket SENSITIVE-b8656b72c3595164 key pkg/version/version.go
Sep-24 11:55:59.720 [Endpoint/12] [ERROR] core.rpc.rpc:: RPC._request: response ERROR srv object_api.read_object_md params { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', version_id: undefined, md_conditions: undefined, encryption: undefined } reqid 2605@fcall://fcall(7quzig5t) took [1.9+0.6=2.5] Error: No such object: obj_id undefined bucket SENSITIVE-b8656b72c3595164 key pkg/version/version.go
    at RpcRequest._set_response (/root/node_modules/noobaa-core/src/rpc/rpc_request.js:130:26)
    at RPC._on_response (/root/node_modules/noobaa-core/src/rpc/rpc.js:426:32)
    at RPC._on_message (/root/node_modules/noobaa-core/src/rpc/rpc.js:762:22)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc.js:597:48)
    at RpcFcallConnection.emit (events.js:315:20)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc_base_conn.js:75:22)
    at RpcFcallConnection.emit (events.js:315:20)
    at RpcRequest._set_response (/root/node_modules/noobaa-core/src/rpc/rpc_request.js:130:26)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at RPC._on_response (/root/node_modules/noobaa-core/src/rpc/rpc.js:426:32)
    at Immediate._onImmediate (/root/node_modules/noobaa-core/src/rpc/rpc_fcall.js:18:33)
    at RPC._on_message (/root/node_modules/noobaa-core/src/rpc/rpc.js:762:22)
    at processImmediate (internal/timers.js:456:21)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc.js:597:48)
    at process.topLevelDomainCallback (domain.js:137:15)
    at RpcFcallConnection.emit (events.js:315:20)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc_base_conn.js:75:22)
    at RpcFcallConnection.emit (events.js:315:20)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at Immediate._onImmediate (/root/node_modules/noobaa-core/src/rpc/rpc_fcall.js:18:33)
    at processImmediate (internal/timers.js:456:21)
    at process.topLevelDomainCallback (domain.js:137:15) {
  rpc_code: 'NO_SUCH_OBJECT'
}
Sep-24 11:55:59.721 [Endpoint/12]    [L0] core.sdk.namespace_s3:: NamespaceS3.read_object_md: hub-local { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', version_id: undefined, md_conditions: undefined, encryption: undefined }
Sep-24 11:55:59.724 [Endpoint/12]    [L0] core.util.signature_utils:: _string_to_sign_v4 method GET pathname /hub-local/pkg/version/version.go search  headers { 'User-Agent': 'aws-sdk-nodejs/2.660.0 linux/v12.18.2 promise', Range: 'bytes=0-4095', 'X-Amz-Content-Sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855', 'Content-Length': '0', Host: '172.17.0.5:6001', 'X-Amz-Date': '20200924T115559Z', Authorization: 'AWS4-HMAC-SHA256 Credential=1EPzXy87z72a2UAVbfya/20200924/us-east-1/s3/aws4_request, SignedHeaders=host;range;x-amz-content-sha256;x-amz-date, Signature=ee766a651ba7fb08d57cd793065cc3afce79ba81b026b4e07ec3936924c40f70', Connection: 'close' } region us-east-1 canonical_str
GET
/hub-local/pkg/version/version.go

host:172.17.0.5:6001
range:bytes=0-4095
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20200924T115559Z

host;range;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
 string_to_sign
AWS4-HMAC-SHA256
20200924T115559Z
20200924/us-east-1/s3/aws4_request
ede4e88035f1a24bb0bb9e06b577761378d31a2c4a335c4bd2d2ceb3ce99b5ca

Sep-24 11:55:59.724 [Endpoint/12]    [L0] core.endpoint.s3.s3_rest:: S3 REQUEST GET /hub-local/pkg/version/version.go op get_object request_id kfgrfqln-aywkz6-rko { 'user-agent': 'aws-sdk-nodejs/2.660.0 linux/v12.18.2 promise', range: 'bytes=0-4095', 'x-amz-content-sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855', 'content-length': '0', host: '172.17.0.5:6001', 'x-amz-date': '20200924T115559Z', authorization: 'AWS4-HMAC-SHA256 Credential=1EPzXy87z72a2UAVbfya/20200924/us-east-1/s3/aws4_request, SignedHeaders=host;range;x-amz-content-sha256;x-amz-date, Signature=ee766a651ba7fb08d57cd793065cc3afce79ba81b026b4e07ec3936924c40f70', connection: 'close' }
Sep-24 11:55:59.725 [Endpoint/12]    [L0] core.server.object_services.object_server:: object_server.read_object_md: { bucket: SENSITIVE-c6d1ca3c1539bd01, key: 'pkg/version/version.go', version_id: undefined, md_conditions: undefined, encryption: undefined }
Sep-24 11:55:59.727 [Endpoint/12]    [L0] core.util.http_utils:: HTTP REPLY RAW GET /hub-local/pkg/version/version.go
Sep-24 11:55:59.735 [Endpoint/12]    [L0] core.server.node_services.node_allocator:: refresh_pool_alloc: updated pool noobaa-default-backing-store nodes [ 'noobaa-default-backing-store-noobaa-pod-2e15336f-noobaa_storage-568c5857' ]
Sep-24 11:55:59.737 [Endpoint/12]   [LOG] core.server.object_services.md_store:: update_object_by_id: 5f6b6ed91b2790000ccff514 { '$set': { 'stats.last_read': 2020-09-24T11:55:59.737Z }, '$inc': { 'stats.reads': 1 } }
Sep-24 11:55:59.738 [Endpoint/12]    [L0] core.sdk.object_io:: READ reader pos 644
Sep-24 11:55:59.739 [Endpoint/12]    [L0] core.sdk.namespace_s3:: NamespaceS3.read_object_md: hub-local { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', version_id: undefined, md_conditions: undefined, encryption: undefined } res { AcceptRanges: 'bytes', LastModified: 2020-09-23T15:50:49.000Z, ContentLength: 644, ETag: '"2502220026a552dd1314bb3cec2712c6"', ContentRange: 'bytes 0-643/644', ContentType: 'application/octet-stream', Metadata: {}, Body: <Buffer 70 61 63 6b 61 67 65 20 76 65 72 73 69 6f 6e 0a 0a 69 6d 70 6f 72 74 20 28 0a 09 22 67 69 74 68 75 62 2e 63 6f 6d 2f 6e 6f 6f 62 61 61 2f 6e 6f 6f 62 ... 594 more bytes> }
Sep-24 11:55:59.740 [Endpoint/12]    [L0] core.util.http_utils:: HTTP REPLY EMPTY HEAD /hub-local-cache/pkg/version/version.go {"host":"192.168.64.132:30798","accept-encoding":"identity","user-agent":"aws-cli/2.0.50 Python/3.8.5 Darwin/19.6.0 source/x86_64 command/s3.cp","x-amz-date":"20200924T115559Z","x-amz-content-sha256":"e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855","authorization":"AWS4-HMAC-SHA256 Credential=1EPzXy87z72a2UAVbfya/20200924/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=18814529ded64dfee69c0191f6f30018e808b7eecb6fb005dba897be20dcc2ee"} 200
Sep-24 11:55:59.741 [Endpoint/12]    [L0] core.sdk.object_io:: upload_object: start upload { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', content_type: undefined, size: 644, xattr: { 'noobaa-namespace-s3-bucket': 'hub-local' }, last_modified_time: 1600876249000 }
Sep-24 11:55:59.743 [Endpoint/12]    [L0] core.server.object_services.object_server:: create_object_upload: { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', content_type: undefined, size: 644, xattr: { 'noobaa-namespace-s3-bucket': 'hub-local' }, last_modified_time: 1600876249000 }
Sep-24 11:55:59.745 [Endpoint/12]    [L0] core.util.signature_utils:: _string_to_sign_v4 method GET pathname /hub-local-cache/pkg/version/version.go search  headers { Host: '192.168.64.132:30798', 'Accept-Encoding': 'identity', 'User-Agent': 'aws-cli/2.0.50 Python/3.8.5 Darwin/19.6.0 source/x86_64 command/s3.cp', 'X-Amz-Date': '20200924T115559Z', 'X-Amz-Content-Sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855', Authorization: 'AWS4-HMAC-SHA256 Credential=1EPzXy87z72a2UAVbfya/20200924/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=e189b45774d632727a9091d6e4077038e742660253e2dec741851dad76ab0a1d' } region us-east-1 canonical_str
GET
/hub-local-cache/pkg/version/version.go

host:192.168.64.132:30798
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20200924T115559Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
 string_to_sign
AWS4-HMAC-SHA256
20200924T115559Z
20200924/us-east-1/s3/aws4_request
56e33f16cdab6882f4b56f2b08513844bca1d0ae6d534b8cd61f0eee8d779545

Sep-24 11:55:59.746 [Endpoint/12]    [L0] core.endpoint.s3.s3_rest:: S3 REQUEST GET /hub-local-cache/pkg/version/version.go op get_object request_id kfgrfqm9-bbvs34-u0y { host: '192.168.64.132:30798', 'accept-encoding': 'identity', 'user-agent': 'aws-cli/2.0.50 Python/3.8.5 Darwin/19.6.0 source/x86_64 command/s3.cp', 'x-amz-date': '20200924T115559Z', 'x-amz-content-sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855', authorization: 'AWS4-HMAC-SHA256 Credential=1EPzXy87z72a2UAVbfya/20200924/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=e189b45774d632727a9091d6e4077038e742660253e2dec741851dad76ab0a1d' }
Sep-24 11:55:59.746 [Endpoint/12]    [L0] core.server.object_services.object_server:: object_server.read_object_md: { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', version_id: undefined, md_conditions: undefined, encryption: undefined }
Sep-24 11:55:59.747 [Endpoint/12]    [L0] core.server.node_services.node_allocator:: refresh_pool_alloc: updated pool system-internal-storage-pool-5f6b6380b1bc730028bc6e02 nodes [ 'noobaa-internal-agent-5f6b6380b1bc730028bc6e03' ]
Sep-24 11:55:59.748 [Endpoint/12]    [L0] core.sdk.namespace_cache:: NamespaceCache.read_object_md: error in cache RpcError: No such object: obj_id undefined bucket SENSITIVE-b8656b72c3595164 key pkg/version/version.go
    at RpcRequest._set_response (/root/node_modules/noobaa-core/src/rpc/rpc_request.js:130:26)
    at RPC._on_response (/root/node_modules/noobaa-core/src/rpc/rpc.js:426:32)
    at RPC._on_message (/root/node_modules/noobaa-core/src/rpc/rpc.js:762:22)
Sep-24 11:55:59.748 [Endpoint/12] [ERROR] CONSOLE:: RPC._on_request: ERROR srv object_api.read_object_md reqid 2609@fcall://fcall(7quzig5t) connid fcall://fcall(7quzig5t) Error: No such object: obj_id undefined bucket SENSITIVE-b8656b72c3595164 key pkg/version/version.go
    at check_object_mode (/root/node_modules/noobaa-core/src/server/object_services/object_server.js:1491:15)
    at find_object_md (/root/node_modules/noobaa-core/src/server/object_services/object_server.js:1413:5)
    at async Object.read_object_md (/root/node_modules/noobaa-core/src/server/object_services/object_server.js:771:17)
Sep-24 11:55:59.748 [Endpoint/12] [ERROR] core.rpc.rpc:: RPC._request: response ERROR srv object_api.read_object_md params { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', version_id: undefined, md_conditions: undefined, encryption: undefined } reqid 2609@fcall://fcall(7quzig5t) took [1.5+0.4=1.9] Error: No such object: obj_id undefined bucket SENSITIVE-b8656b72c3595164 key pkg/version/version.go
    at RpcRequest._set_response (/root/node_modules/noobaa-core/src/rpc/rpc_request.js:130:26)
    at RPC._on_response (/root/node_modules/noobaa-core/src/rpc/rpc.js:426:32)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc.js:597:48)
    at RPC._on_message (/root/node_modules/noobaa-core/src/rpc/rpc.js:762:22)
    at RpcFcallConnection.emit (events.js:315:20)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc.js:597:48)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at RpcFcallConnection.emit (events.js:315:20)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc_base_conn.js:75:22)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at RpcFcallConnection.emit (events.js:315:20)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc_base_conn.js:75:22)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at RpcFcallConnection.emit (events.js:315:20)
    at Immediate._onImmediate (/root/node_modules/noobaa-core/src/rpc/rpc_fcall.js:18:33)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at processImmediate (internal/timers.js:456:21)
    at Immediate._onImmediate (/root/node_modules/noobaa-core/src/rpc/rpc_fcall.js:18:33)
    at process.topLevelDomainCallback (domain.js:137:15) {
    at processImmediate (internal/timers.js:456:21)
  rpc_code: 'NO_SUCH_OBJECT'
    at process.topLevelDomainCallback (domain.js:137:15)
}
Sep-24 11:55:59.748 [Endpoint/12]    [L0] core.sdk.namespace_s3:: NamespaceS3.read_object_md: hub-local { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', version_id: undefined, md_conditions: undefined, encryption: undefined }
Sep-24 11:55:59.765 [Endpoint/12]    [L0] core.util.signature_utils:: _string_to_sign_v4 method GET pathname /hub-local/pkg/version/version.go search  headers { 'User-Agent': 'aws-sdk-nodejs/2.660.0 linux/v12.18.2 promise', Range: 'bytes=0-4095', 'X-Amz-Content-Sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855', 'Content-Length': '0', Host: '172.17.0.5:6001', 'X-Amz-Date': '20200924T115559Z', Authorization: 'AWS4-HMAC-SHA256 Credential=1EPzXy87z72a2UAVbfya/20200924/us-east-1/s3/aws4_request, SignedHeaders=host;range;x-amz-content-sha256;x-amz-date, Signature=ee766a651ba7fb08d57cd793065cc3afce79ba81b026b4e07ec3936924c40f70', Connection: 'close' } region us-east-1 canonical_str
GET
/hub-local/pkg/version/version.go

host:172.17.0.5:6001
range:bytes=0-4095
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20200924T115559Z

host;range;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
 string_to_sign
AWS4-HMAC-SHA256
20200924T115559Z
20200924/us-east-1/s3/aws4_request
ede4e88035f1a24bb0bb9e06b577761378d31a2c4a335c4bd2d2ceb3ce99b5ca

Sep-24 11:55:59.767 [Endpoint/12]    [L0] core.endpoint.s3.s3_rest:: S3 REQUEST GET /hub-local/pkg/version/version.go op get_object request_id kfgrfqmf-bffq7b-1bnw { 'user-agent': 'aws-sdk-nodejs/2.660.0 linux/v12.18.2 promise', range: 'bytes=0-4095', 'x-amz-content-sha256': 'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855', 'content-length': '0', host: '172.17.0.5:6001', 'x-amz-date': '20200924T115559Z', authorization: 'AWS4-HMAC-SHA256 Credential=1EPzXy87z72a2UAVbfya/20200924/us-east-1/s3/aws4_request, SignedHeaders=host;range;x-amz-content-sha256;x-amz-date, Signature=ee766a651ba7fb08d57cd793065cc3afce79ba81b026b4e07ec3936924c40f70', connection: 'close' }
Sep-24 11:55:59.768 [Endpoint/12]    [L0] core.server.object_services.object_server:: object_server.read_object_md: { bucket: SENSITIVE-c6d1ca3c1539bd01, key: 'pkg/version/version.go', version_id: undefined, md_conditions: undefined, encryption: undefined }
Sep-24 11:55:59.771 [Endpoint/12]    [L0] core.sdk.object_io:: UPLOAD: { obj_id: '5f6c894fdcd2ee000c58ff26', bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go' } streaming to SENSITIVE-b8656b72c3595164 pkg/version/version.go
Sep-24 11:55:59.777 [Endpoint/12]    [L0] core.sdk.object_io:: UPLOAD: part 0 ChunkAPI {
  chunk_info: { data: undefined, size: 644, pos: 0, chunk_coder_config: { digest_type: 'sha384', frag_digest_type: 'sha1', compress_type: 'snappy', cipher_type: 'aes-256-gcm', replicas: 1, data_frags: 1, parity_frags: 0 }, frag_size: 392, compress_size: 392, digest_b64: '+aCkScwbASw64oUFEujpvODG+ZUzfjnxf8xy8363H85pzelx5wnA6P3zLepGt6iQ', cipher_key_b64: 'uIlQilBPMqsLnJb5dorJ4LG7g+SQyz9EUiBLildZjCQ=', frags: [ { data_index: 0, data: <Buffer 03 13 20 f8 35 f3 77 60 40 5f 0b 2b eb b4 a4 aa fe 55 64 9b fd 7a fd a3 31 8a c1 4b 8b 47 41 f4 d2 21 10 d1 57 2b 0f 46 38 76 f8 ef c5 2e e9 c3 3a e0 ... 342 more bytes>, digest_b64: 'krP9xUlARcYQmYzarp+y1QEX9J0=', blocks: [] } ], tier_id: '5f6c891cf28864002de18eb0', bucket_id: '5f6c891cf28864002de18eb2', parts: [ { obj_id: '5f6c894fdcd2ee000c58ff26', chunk_id: undefined, multipart_id: undefined, start: 0, end: 644, seq: 0, uncommitted: true } ] },
  system_store: undefined,
  had_errors: false
}
Sep-24 11:55:59.782 [Endpoint/12]    [L0] core.server.object_services.map_server:: GetMapping.find_dups: found keys 1
Sep-24 11:55:59.784 [Endpoint/12]    [L0] core.util.http_utils:: HTTP REPLY RAW GET /hub-local/pkg/version/version.go
Sep-24 11:55:59.784 [Endpoint/12]    [L0] core.server.object_services.map_server:: GetMapping.find_dups: dup_chunks []
Sep-24 11:55:59.804 [Endpoint/12]   [LOG] core.server.object_services.md_store:: update_object_by_id: 5f6b6ed91b2790000ccff514 { '$set': { 'stats.last_read': 2020-09-24T11:55:59.803Z }, '$inc': { 'stats.reads': 1 } }
Sep-24 11:55:59.806 [Endpoint/12]    [L0] core.rpc.ice:: Got error Error: connect ECONNREFUSED 79.179.237.79:60100
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1141:16) {
  errno: 'ECONNREFUSED',
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '79.179.237.79',
  port: 60100
}
Sep-24 11:55:59.806 [Endpoint/12]    [L0] core.sdk.object_io:: READ reader pos 644
Sep-24 11:55:59.807 [Endpoint/12]    [L0] core.sdk.namespace_s3:: NamespaceS3.read_object_md: hub-local { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', version_id: undefined, md_conditions: undefined, encryption: undefined } res { AcceptRanges: 'bytes', LastModified: 2020-09-23T15:50:49.000Z, ContentLength: 644, ETag: '"2502220026a552dd1314bb3cec2712c6"', ContentRange: 'bytes 0-643/644', ContentType: 'application/octet-stream', Metadata: {}, Body: <Buffer 70 61 63 6b 61 67 65 20 76 65 72 73 69 6f 6e 0a 0a 69 6d 70 6f 72 74 20 28 0a 09 22 67 69 74 68 75 62 2e 63 6f 6d 2f 6e 6f 6f 62 61 61 2f 6e 6f 6f 62 ... 594 more bytes> }
Sep-24 11:55:59.808 [Endpoint/12]    [L0] core.util.http_utils:: HTTP REPLY RAW GET /hub-local-cache/pkg/version/version.go
Sep-24 11:55:59.808 [Endpoint/12]    [L0] core.sdk.object_io:: upload_object: start upload { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', content_type: undefined, size: 644, xattr: { 'noobaa-namespace-s3-bucket': 'hub-local' }, last_modified_time: 1600876249000 }
Sep-24 11:55:59.809 [Endpoint/12]    [L0] core.server.object_services.object_server:: create_object_upload: { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', content_type: undefined, size: 644, xattr: { 'noobaa-namespace-s3-bucket': 'hub-local' }, last_modified_time: 1600876249000 }
Sep-24 11:55:59.811 [Endpoint/12]    [L0] core.sdk.object_io:: UPLOAD: { obj_id: '5f6c894fdcd2ee000c58ff28', bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go' } streaming to SENSITIVE-b8656b72c3595164 pkg/version/version.go
Sep-24 11:55:59.813 [Endpoint/12]    [L0] core.sdk.object_io:: UPLOAD: part 0 ChunkAPI {
  chunk_info: { data: undefined, size: 644, pos: 0, chunk_coder_config: { digest_type: 'sha384', frag_digest_type: 'sha1', compress_type: 'snappy', cipher_type: 'aes-256-gcm', replicas: 1, data_frags: 1, parity_frags: 0 }, frag_size: 392, compress_size: 392, digest_b64: '+aCkScwbASw64oUFEujpvODG+ZUzfjnxf8xy8363H85pzelx5wnA6P3zLepGt6iQ', cipher_key_b64: 'nVR6QJgvicilr5ZazPPdGx3D3a37sGAoXEcYYFLAZhE=', frags: [ { data_index: 0, data: <Buffer f9 f6 36 fe e2 6a 25 ff 16 36 50 25 8a 59 b7 55 34 df e6 ce fe ad 1c e3 b7 ac 64 92 12 a0 57 55 73 63 64 85 31 f9 01 e9 df 0c d6 cf ad 7c 15 7b bf bb ... 342 more bytes>, digest_b64: 'LhpV592Q5PO0WP20xCFkaFqvNr8=', blocks: [] } ], tier_id: '5f6c891cf28864002de18eb0', bucket_id: '5f6c891cf28864002de18eb2', parts: [ { obj_id: '5f6c894fdcd2ee000c58ff28', chunk_id: undefined, multipart_id: undefined, start: 0, end: 644, seq: 0, uncommitted: true } ] },
  system_store: undefined,
  had_errors: false
}
Sep-24 11:55:59.814 [Endpoint/12]    [L0] core.server.object_services.map_server:: GetMapping.find_dups: found keys 1
Sep-24 11:55:59.861 [Endpoint/12]    [L0] core.server.object_services.map_server:: GetMapping.find_dups: dup_chunks []
Sep-24 11:55:59.967 [Endpoint/12]    [L0] core.sdk.object_io:: upload_object: complete upload { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', last_modified_time: 1600876249000, obj_id: '5f6c894fdcd2ee000c58ff28', size: 644, num_parts: 1, md5_b64: 'JQIiACalUt0TFLs87CcSxg==' }
Sep-24 11:55:59.969 [Endpoint/12]    [L0] core.sdk.object_io:: upload_object: complete upload { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', last_modified_time: 1600876249000, obj_id: '5f6c894fdcd2ee000c58ff26', size: 644, num_parts: 1, md5_b64: 'JQIiACalUt0TFLs87CcSxg==' }
Sep-24 11:55:59.978 [Endpoint/12]   [LOG] core.server.object_services.md_store:: update_object_by_id: 5f6c894fdcd2ee000c58ff28 { '$set': { md5_b64: 'JQIiACalUt0TFLs87CcSxg==', size: 644, num_parts: 1, etag: '2502220026a552dd1314bb3cec2712c6', create_time: 2020-09-24T11:55:59.974Z, cache_last_valid_time: 2020-09-24T11:55:59.974Z, version_seq: 61, last_modified_time: 2020-09-23T15:50:49.000Z }, '$unset': { upload_size: 1, upload_started: 1 } }
Sep-24 11:55:59.979 [Endpoint/12]   [LOG] core.server.object_services.md_store:: update_object_by_id: 5f6c894fdcd2ee000c58ff26 { '$set': { md5_b64: 'JQIiACalUt0TFLs87CcSxg==', size: 644, num_parts: 1, etag: '2502220026a552dd1314bb3cec2712c6', create_time: 2020-09-24T11:55:59.974Z, cache_last_valid_time: 2020-09-24T11:55:59.974Z, version_seq: 62, last_modified_time: 2020-09-23T15:50:49.000Z }, '$unset': { upload_size: 1, upload_started: 1 } }
Sep-24 11:55:59.980 [Endpoint/12]    [L0] core.server.notifications.dispatcher:: Adding ActivityLog entry { system: 5f6b6380b1bc730028bc6e02, level: 'info', event: 'obj.uploaded', obj: 5f6c894fdcd2ee000c58ff28, actor: 5f6b6380b1bc730028bc6e01, desc: SENSITIVE-4273cbe7d2f91916 }
Sep-24 11:55:59.991 [Endpoint/12] [ERROR] CONSOLE:: RPC._on_request: ERROR srv object_api.complete_object_upload reqid 2618@fcall://fcall(7quzig5t) connid fcall://fcall(7quzig5t) MongoError: E11000 duplicate key error collection: nbcore.objectmds index: latest_version_index dup key: { : ObjectId('5f6c891cf28864002de18eb2'), : "pkg/version/version.go", : null }
    at Function.create (/root/node_modules/noobaa-core/node_modules/mongodb-core/lib/error.js:43:12)
Sep-24 11:55:59.991 [Endpoint/12]    [L0] core.util.mongo_client:: _init_collection: created collection activitylogs
    at toError (/root/node_modules/noobaa-core/node_modules/mongodb/lib/utils.js:149:22)
    at /root/node_modules/noobaa-core/node_modules/mongodb/lib/operations/collection_ops.js:1465:39
    at /root/node_modules/noobaa-core/node_modules/mongodb-core/lib/connection/pool.js:397:18
    at processTicksAndRejections (internal/process/task_queues.js:79:11)
Sep-24 11:55:59.995 [Endpoint/12]    [L0] core.util.mongo_client:: _init_collection: created index activitylogs time_1
Sep-24 11:55:59.995 [Endpoint/12] [ERROR] core.rpc.rpc:: RPC._request: response ERROR srv object_api.complete_object_upload params { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', last_modified_time: 1600876249000, obj_id: '5f6c894fdcd2ee000c58ff26', size: 644, num_parts: 1, md5_b64: 'JQIiACalUt0TFLs87CcSxg==' } reqid 2618@fcall://fcall(7quzig5t) took [22.0+3.9=26.0] Error: E11000 duplicate key error collection: nbcore.objectmds index: latest_version_index dup key: { : ObjectId('5f6c891cf28864002de18eb2'), : "pkg/version/version.go", : null }
    at RpcRequest._set_response (/root/node_modules/noobaa-core/src/rpc/rpc_request.js:130:26)
    at RPC._on_response (/root/node_modules/noobaa-core/src/rpc/rpc.js:426:32)
    at RPC._on_message (/root/node_modules/noobaa-core/src/rpc/rpc.js:762:22)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc.js:597:48)
    at RpcFcallConnection.emit (events.js:315:20)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc_base_conn.js:75:22)
    at RpcFcallConnection.emit (events.js:315:20)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at Immediate._onImmediate (/root/node_modules/noobaa-core/src/rpc/rpc_fcall.js:18:33)
    at processImmediate (internal/timers.js:456:21)
    at process.topLevelDomainCallback (domain.js:137:15)
Sep-24 11:55:59.996 [Endpoint/12]  [WARN] core.sdk.object_io:: upload_object: failed upload { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', last_modified_time: 1600876249000, obj_id: '5f6c894fdcd2ee000c58ff26', size: 644, num_parts: 1, md5_b64: 'JQIiACalUt0TFLs87CcSxg==' } RpcError: E11000 duplicate key error collection: nbcore.objectmds index: latest_version_index dup key: { : ObjectId('5f6c891cf28864002de18eb2'), : "pkg/version/version.go", : null }
    at RpcRequest._set_response (/root/node_modules/noobaa-core/src/rpc/rpc_request.js:130:26)
    at RPC._on_response (/root/node_modules/noobaa-core/src/rpc/rpc.js:426:32)
    at RPC._on_message (/root/node_modules/noobaa-core/src/rpc/rpc.js:762:22)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc.js:597:48)
    at RpcFcallConnection.emit (events.js:315:20)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc_base_conn.js:75:22)
    at RpcFcallConnection.emit (events.js:315:20)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at Immediate._onImmediate (/root/node_modules/noobaa-core/src/rpc/rpc_fcall.js:18:33)
    at processImmediate (internal/timers.js:456:21)
    at process.topLevelDomainCallback (domain.js:137:15) {
  rpc_code: 'INTERNAL',
  rpc_data: { retryable: true }
}
Sep-24 11:56:00.001 [Endpoint/12]    [L0] core.sdk.object_io:: upload_object: aborted object upload { bucket: SENSITIVE-b8656b72c3595164, key: 'pkg/version/version.go', last_modified_time: 1600876249000, obj_id: '5f6c894fdcd2ee000c58ff26', size: 644, num_parts: 1, md5_b64: 'JQIiACalUt0TFLs87CcSxg==' }
Sep-24 11:56:00.002 [Endpoint/12] [ERROR] CONSOLE:: (node:12) UnhandledPromiseRejectionWarning: Error: E11000 duplicate key error collection: nbcore.objectmds index: latest_version_index dup key: { : ObjectId('5f6c891cf28864002de18eb2'), : "pkg/version/version.go", : null }
    at RpcRequest._set_response (/root/node_modules/noobaa-core/src/rpc/rpc_request.js:130:26)
    at RPC._on_response (/root/node_modules/noobaa-core/src/rpc/rpc.js:426:32)
    at RPC._on_message (/root/node_modules/noobaa-core/src/rpc/rpc.js:762:22)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc.js:597:48)
    at RpcFcallConnection.emit (events.js:315:20)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at RpcFcallConnection.<anonymous> (/root/node_modules/noobaa-core/src/rpc/rpc_base_conn.js:75:22)
    at RpcFcallConnection.emit (events.js:315:20)
    at RpcFcallConnection.EventEmitter.emit (domain.js:482:12)
    at Immediate._onImmediate (/root/node_modules/noobaa-core/src/rpc/rpc_fcall.js:18:33)
    at processImmediate (internal/timers.js:456:21)
    at process.topLevelDomainCallback (domain.js:137:15)
Sep-24 11:56:00.002 [Endpoint/12] [ERROR] CONSOLE:: (node:12) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 7)
Sep-24 11:56:06.091 [Endpoint/12]  [WARN] core.util.mongo_client:: INVALID_SCHEMA_DB systems ERRORS [
  { keyword: 'enum', dataPath: '.system_address[6].api', schemaPath: '#/properties/system_address/items/properties/api/enum', params: { allowedValues: [ 'mgmt', 's3', 'md', 'bg', 'hosted_agents', 'mongodb', [length]: 6 ] }, message: 'should be equal to one of the allowed values', schema: [ 'mgmt', 's3', 'md', 'bg', 'hosted_agents', 'mongodb', [length]: 6 ], parentSchema: { type: 'string', enum: [ 'mgmt', 's3', 'md', 'bg', 'hosted_agents', 'mongodb', [length]: 6 ] }, data: 'metrics' },
  [length]: 1
] DOC { _id: 5f6b6380b1bc730028bc6e02, name: 'noobaa', owner: 5f6b6380b1bc730028bc6e01, state: { mode: 'READY', last_update: 1600873375244 }, resources: { agent_installer: 'noobaa-setup.exe', s3rest_installer: 'noobaa-s3rest.exe', linux_agent_installer: 'noobaa-setup' }, n2n_config: { tcp_tls: true, tcp_active: true, tcp_permanent_passive: { min: 60101, max: 60600 }, udp_dtls: true, udp_port: true }, debug_level: 0, mongo_upgrade: { blocks_to_buckets: true }, last_stats_report: 1600875449851, freemium_cap: { phone_home_upgraded: false, phone_home_notified: false, cap_terabytes: 20 }, current_version: '5.6.0-a8b8f83', upgrade_history: { successful_upgrades: [ [length]: 0 ] }, system_address: [ { service: 'noobaa-db', port: 27017, secure: false, api: 'mongodb', weight: 0, kind: 'INTERNAL', hostname: 'noobaa-db.default.svc.cluster.local' }, { service: 'noobaa-mgmt', port: 443, secure: true, api: 'mgmt', weight: 0, kind: 'INTERNAL', hostname: 'noobaa-mgmt.default.svc.cluster.local' }, { service: 'noobaa-mgmt', port: 80, secure: false, api: 'mgmt', weight: 0, kind: 'INTERNAL', hostname: 'noobaa-mgmt.default.svc.cluster.local' }, { service: 'noobaa-mgmt', port: 8445, secure: true, api: 'bg', weight: 0, kind: 'INTERNAL', hostname: 'noobaa-mgmt.default.svc.cluster.local' }, { service: 'noobaa-mgmt', port: 8446, secure: true, api: 'hosted_agents', weight: 0, kind: 'INTERNAL', hostname: 'noobaa-mgmt.default.svc.cluster.local' }, { service: 's3', port: 443, secure: true, api: 's3', weight: 0, kind: 'INTERNAL', hostname: 's3.default.svc.cluster.local' }, { service: 's3', port: 7004, secure: false, api: 'metrics', weight: 0, kind: 'INTERNAL', hostname: 's3.default.svc.cluster.local' }, { service: 's3', port: 80, secure: false, api: 's3', weight: 0, kind: 'INTERNAL', hostname: 's3.default.svc.cluster.local' }, { service: 's3', port: 8444, secure: true, api: 'md', weight: 0, kind: 'INTERNAL', hostname: 's3.default.svc.cluster.local' }, [length]: 9 ], global_last_update: 1600948472769 }
Sep-24 11:56:07.301 [Endpoint/12]  [WARN] core.util.mongo_client:: INVALID_SCHEMA_DB systems ERRORS [
  { keyword: 'enum', dataPath: '.system_address[6].api', schemaPath: '#/properties/system_address/items/properties/api/enum', params: { allowedValues: [ 'mgmt', 's3', 'md', 'bg', 'hosted_agents', 'mongodb', [length]: 6 ] }, message: 'should be equal to one of the allowed values', schema: [ 'mgmt', 's3', 'md', 'bg', 'hosted_agents', 'mongodb', [length]: 6 ], parentSchema: { type: 'string', enum: [ 'mgmt', 's3', 'md', 'bg', 'hosted_agents', 'mongodb', [length]: 6 ] }, data: 'metrics' },
  [length]: 1
] DOC { _id: 5f6b6380b1bc730028bc6e02, name: 'noobaa', owner: 5f6b6380b1bc730028bc6e01, state: { mode: 'READY', last_update: 1600873375244 }, resources: { agent_installer: 'noobaa-setup.exe', s3rest_installer: 'noobaa-s3rest.exe', linux_agent_installer: 'noobaa-setup' }, n2n_config: { tcp_tls: true, tcp_active: true, tcp_permanent_passive: { min: 60101, max: 60600 }, udp_dtls: true, udp_port: true }, debug_level: 0, mongo_upgrade: { blocks_to_buckets: true }, last_stats_report: 1600875449851, freemium_cap: { phone_home_upgraded: false, phone_home_notified: false, cap_terabytes: 20 }, current_version: '5.6.0-a8b8f83', upgrade_history: { successful_upgrades: [ [length]: 0 ] }, system_address: [ { service: 'noobaa-db', port: 27017, secure: false, api: 'mongodb', weight: 0, kind: 'INTERNAL', hostname: 'noobaa-db.default.svc.cluster.local' }, { service: 'noobaa-mgmt', port: 443, secure: true, api: 'mgmt', weight: 0, kind: 'INTERNAL', hostname: 'noobaa-mgmt.default.svc.cluster.local' }, { service: 'noobaa-mgmt', port: 80, secure: false, api: 'mgmt', weight: 0, kind: 'INTERNAL', hostname: 'noobaa-mgmt.default.svc.cluster.local' }, { service: 'noobaa-mgmt', port: 8445, secure: true, api: 'bg', weight: 0, kind: 'INTERNAL', hostname: 'noobaa-mgmt.default.svc.cluster.local' }, { service: 'noobaa-mgmt', port: 8446, secure: true, api: 'hosted_agents', weight: 0, kind: 'INTERNAL', hostname: 'noobaa-mgmt.default.svc.cluster.local' }, { service: 's3', port: 443, secure: true, api: 's3', weight: 0, kind: 'INTERNAL', hostname: 's3.default.svc.cluster.local' }, { service: 's3', port: 7004, secure: false, api: 'metrics', weight: 0, kind: 'INTERNAL', hostname: 's3.default.svc.cluster.local' }, { service: 's3', port: 80, secure: false, api: 's3', weight: 0, kind: 'INTERNAL', hostname: 's3.default.svc.cluster.local' }, { service: 's3', port: 8444, secure: true, api: 'md', weight: 0, kind: 'INTERNAL', hostname: 's3.default.svc.cluster.local' }, [length]: 9 ], global_last_update: 1600948475768 }
baum commented 3 years ago

Reproduced the issue with the current master version. After reading a small object present in the S3 remote resource, but not in the NooBaa cache, the issue happens. The resulting DB state is:

>  db.objectmds.find({key:"pkg/version/version.go"}).pretty()
{
    "_id" : ObjectId("61079e81d14c8e00095d3306"),
    "system" : ObjectId("61079bba2bd1e4003063bdad"),
    "bucket" : ObjectId("61079d312bd1e4003063bdd0"),
    "key" : "pkg/version/version.go",
    "content_type" : "application/octet-stream",
    "cache_last_valid_time" : ISODate("2021-08-02T07:28:03.802Z"),
    "size" : 667,
    "xattr" : {
        "noobaa-namespace-s3-bucket" : "baum"
    },
    "create_time" : ISODate("2021-08-02T07:28:03.802Z"),
    "etag" : "d2785f4d86d2dd2312eb6d5b7b9ebed5",
    "last_modified_time" : ISODate("2021-08-01T09:25:48Z"),
    "md5_b64" : "0nhfTYbS3SMS621be56+1Q==",
    "num_parts" : 1,
    "version_seq" : 1,
    "deleted" : ISODate("2021-08-02T07:28:04.304Z"),
    "version_past" : true,
    "reclaimed" : ISODate("2021-08-02T07:28:26.362Z")
}
{
    "_id" : ObjectId("61079e83d14c8e00095d330b"),
    "system" : ObjectId("61079bba2bd1e4003063bdad"),
    "bucket" : ObjectId("61079d312bd1e4003063bdd0"),
    "key" : "pkg/version/version.go",
    "content_type" : "application/octet-stream",
    "cache_last_valid_time" : ISODate("2021-08-02T07:28:04.299Z"),
    "size" : 667,
    "xattr" : {
        "noobaa-namespace-s3-bucket" : "baum"
    },
    "create_time" : ISODate("2021-08-02T07:28:04.299Z"),
    "etag" : "d2785f4d86d2dd2312eb6d5b7b9ebed5",
    "last_modified_time" : ISODate("2021-08-01T09:25:48Z"),
    "md5_b64" : "0nhfTYbS3SMS621be56+1Q==",
    "num_parts" : 1,
    "version_seq" : 2
}

According to stack trace logs, while reading an object AWS client issues first S3 Object HEAD and then S3 Object GET. Both operations call NS CACHE read_object_md():

https://github.com/noobaa/noobaa-core/blob/af0e28031b4be38230915a7b38a867db36c86750/src/sdk/namespace_cache.js#L211-L300

Since the object is not in the db.objectmds, and small (<4K) read_object_md() performs md update by running object_io.upload_object_range() in the background, resulting a race between S3 HEAD and GET ops:

https://github.com/noobaa/noobaa-core/blob/af0e28031b4be38230915a7b38a867db36c86750/src/sdk/namespace_cache.js#L256-L280

baum commented 3 years ago

if in the NS CACHE read_object_md() flow upload_object() is awaited in the foreground to avoid the race, the result for the same s3 cp s3://hub-local-cache/pkg/version/version.go - is

> db.objectmds.find({key:"pkg/version/version.go"}).pretty()
{
    "_id" : ObjectId("61081a447dc003000842b01e"),
    "system" : ObjectId("6108183630a4bc0029bc6959"),
    "bucket" : ObjectId("610819c530a4bc0029bc697d"),
    "key" : "pkg/version/version.go",
    "content_type" : "application/octet-stream",
    "upload_size" : 0,
    "upload_started" : ObjectId("61081a447dc003000842b01e"),
    "cache_last_valid_time" : ISODate("2021-08-02T16:16:04.697Z"),
    "size" : 667,
    "xattr" : {
        "noobaa-namespace-s3-bucket" : "baum"
    },
    "deleted" : ISODate("2021-08-02T16:16:14.790Z"),
    "reclaimed" : ISODate("2021-08-02T16:16:35.067Z")
}
{
    "_id" : ObjectId("61081a757dc003000842b020"),
    "system" : ObjectId("6108183630a4bc0029bc6959"),
    "bucket" : ObjectId("610819c530a4bc0029bc697d"),
    "key" : "pkg/version/version.go",
    "content_type" : "application/octet-stream",
    "upload_size" : 0,
    "upload_started" : ObjectId("61081a757dc003000842b020"),
    "cache_last_valid_time" : ISODate("2021-08-02T16:16:53.156Z"),
    "size" : 667,
    "xattr" : {
        "noobaa-namespace-s3-bucket" : "baum"
    },
    "deleted" : ISODate("2021-08-02T16:16:57.743Z"),
    "reclaimed" : ISODate("2021-08-02T16:17:05.142Z")
}
{
    "_id" : ObjectId("610821f77dc003000842b022"),
    "system" : ObjectId("6108183630a4bc0029bc6959"),
    "bucket" : ObjectId("610819c530a4bc0029bc697d"),
    "key" : "pkg/version/version.go",
    "content_type" : "application/octet-stream",
    "cache_last_valid_time" : ISODate("2021-08-02T16:48:58.356Z"),
    "size" : 667,
    "xattr" : {
        "noobaa-namespace-s3-bucket" : "baum"
    },
    "create_time" : ISODate("2021-08-02T16:48:58.356Z"),
    "etag" : "d2785f4d86d2dd2312eb6d5b7b9ebed5",
    "last_modified_time" : ISODate("2021-08-01T09:25:48Z"),
    "md5_b64" : "0nhfTYbS3SMS621be56+1Q==",
    "num_parts" : 1,
    "version_seq" : 1,
    "stats" : {
        "last_read" : ISODate("2021-08-02T16:49:00.257Z"),
        "reads" : 1
    }
}

This change would resolve the UnhandledPromiseRejectionWarning Error

github-actions[bot] commented 1 month ago

This issue had no activity for too long - it will now be labeled stale. Update it to prevent it from getting closed.

github-actions[bot] commented 3 days ago

This issue is stale and had no activity for too long - it will now be closed.