noobaa-core: HPO 659: Mix read/write with md5 checking halts all I/O on all metalLB IP's and does not recover unless noobaa pod restart

Environment info

  • NooBaa Version: [root@c83f1-app1 ~]# noobaa status INFO[0000] CLI version: 5.9.2 INFO[0000] noobaa-image: noobaa/noobaa-core:nsfs_backport_5.9-20220331 INFO[0000] operator-image: quay.io/rhceph-dev/odf4-mcg-rhel8-operator@sha256:01a31a47a43f01c333981056526317dfec70d1072dbd335c8386e0b3f63ef052 INFO[0000] noobaa-db-image: quay.io/rhceph-dev/rhel8-postgresql-12@sha256:98990a28bec6aa05b70411ea5bd9c332939aea02d9d61eedf7422a32cfa0be54
  • Platform: [root@c83f1-app1 ~]# oc get csv NAME DISPLAY VERSION REPLACES PHASE mcg-operator.v4.9.5 NooBaa Operator 4.9.5 mcg-operator.v4.9.4 Succeeded ocs-operator.v4.9.5 OpenShift Container Storage 4.9.5 ocs-operator.v4.9.4 Succeeded odf-operator.v4.9.5 OpenShift Data Foundation 4.9.5 odf-operator.v4.9.4 Succeeded

Actual behavior

This is not the same as issue 6930.

In this issue that I am opening, it is true that the node remained in the Ready state so I don’t expect any IP failover. This defect is not about metallb IP’s not failing over. In this defect, I/O was running to metallb IP 172.20.100.31 which is for node master1. On node master0 , in the CNSA scale core pod, (namespace ibm-spectrum-scale), mmshutdown was issued for just that node. The other nodes remained active and with the filesystem mounted. Master0 has metallb IP 172.20.100.30. There was no I/O going to that IP.

What was observed after mmshutdown on master0 was that all I/O going to 172.20.100.31 stopped. Because of issue 6930, there was no failover. That is fine and expected. But what is not expected is for all I/O to stop.

sh-4.4# date; mmshutdown
Tue Apr  5 17:10:28 UTC 2022
Tue Apr  5 17:10:28 UTC 2022: mmshutdown: Starting force unmount of GPFS file systems
Tue Apr  5 17:10:34 UTC 2022: mmshutdown: Shutting down GPFS daemons
Shutting down!

When mmshutdown was issued, the noobaa endpoint pods only error was Stale file handle

Logs show stale file handle

pod/noobaa-endpoint-7fdb5b75fd-t99nd/endpoint] Apr-5 17:12:26.930 [Endpoint/14] [ERROR] core.endpoint.s3.s3_rest:: S3 ERROR <?xml version="1.0" encoding="UTF-8"?><Error><Code>InternalError</Code><Message>We encountered an internal error. Please try again.</Message><Resource>/s5001b85</Resource><RequestId>l1mefzt6-3wj6yz-8x</RequestId></Error> PUT /s5001b85 {"host":"172.20.100.30","accept-encoding":"identity","user-agent":"aws-cli/2.3.2 Python/3.8.8 Linux/4.18.0-240.el8.x86_64 exe/x86_64.rhel.8 prompt/off command/s3.mb","x-amz-date":"20220405T171225Z","x-amz-content-sha256":"61d056dc66f1882c0f4053be381523a7a28d384abde04fcf5b0021c716bb0ea1","authorization":"AWS4-HMAC-SHA256 Credential=QzhyXj9wVDH9DvnK97L9/20220405/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=6d9fa5c22501bfed4f312ac47621b6cec691bf1cf8f719e8250fcdc0f61522f1","content-length":"154"} Error: Stale file handle
[pod/noobaa-endpoint-7fdb5b75fd-t99nd/endpoint] Apr-5 17:12:27.589 [Endpoint/14]    [L0] core.sdk.bucketspace_nb:: could not create underlying directory - nsfs, deleting bucket [Error: Stale file handle] { code: 'Unknown system error -116' }
[pod/noobaa-endpoint-7fdb5b75fd-t99nd/endpoint] Apr-5 17:12:27.793 [Endpoint/14] [ERROR] core.endpoint.s3.s3_rest:: S3 ERROR <?xml version="1.0" encoding="UTF-8"?><Error><Code>InternalError</Code><Message>We encountered an internal error. Please try again.</Message><Resource>/s5001b85</Resource><RequestId>l1meg1if-7apxvy-1bas</RequestId></Error> PUT /s5001b85 {"host":"172.20.100.30","accept-encoding":"identity","user-agent":"aws-cli/2.3.2 Python/3.8.8 Linux/4.18.0-240.el8.x86_64 exe/x86_64.rhel.8 prompt/off command/s3.mb","x-amz-date":"20220405T171227Z","x-amz-content-sha256":"61d056dc66f1882c0f4053be381523a7a28d384abde04fcf5b0021c716bb0ea1","authorization":"AWS4-HMAC-SHA256 Credential=QzhyXj9wVDH9DvnK97L9/20220405/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=bb34c5aa7ed665ae73a2d172ab33d4056c2611ad2c09331ece80089cff46df05","content-length":"154"} Error: Stale file handle
[root@c83f1-app1 ~

This error is a bit odd because it is on the endpoint pod that was for master0. Master0’s metallb IP was 172.20.100.30. Cosbench workload was only set up for 172.20.100.31.

An additional observation is that s3 command for list will work but not for write.

[root@c83f1-dan4 RW_workloads]# date; s5001_2_31 ls
Tue Apr  5 18:33:40 EDT 2022
2022-04-05 18:33:43 s5001b100
2022-04-05 18:33:43 s5001b63
2022-04-05 18:33:43 s5001b62
2022-04-05 18:33:43 s5001b61


[root@c83f1-dan4 RW_workloads]# date;  s5001_2_31 cp alias_commands s3://s5001b1
Tue Apr  5 18:35:36 EDT 2022
^C^Cfatal error:
^CError in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "concurrent/futures/thread.py", line 40, in _python_exit
  File "threading.py", line 1011, in join
  File "threading.py", line 1027, in _wait_for_tstate_lock
KeyboardInterrupt
[root@c83f1-dan4 RW_workloads]# date
Tue Apr  5 18:36:43 EDT 2022
[root@c83f1-dan4 RW_workloads]#

All future PUT to 172.20.100.31 and 172.20.100.32, get a timeout (if I don’t CTL-C) and the endpoint pods record a “Error: Semaphore Timeout” From 31 and 32, we can do GET and we can read from the Noobaa database. If we rsh into the endpoint pods for the IP’s of 172.20100.31 and 172.20.100.32, we see that Spectrum Scale is still mounted in the correct place and we can write to it manually with touch file. So, this tells us that the IP’s 31 and 32 are still alive and that the noobaa db is still online. It also tells us that the Spectrum Scale filesystem is still mounted and writable. The timeout on the subsequent PUT tell us that it makes a connection request but never gets a response.

The endpoint pods never restarted and they sill have their labels.

Also, In the scale core pod we run mmhealth node show -N all and we see that everything is HEALTHY, except of course on the one node that we did mmshutdown.

  sh-4.4# mmhealth node show

Node name:      master1-daemon
Node status:    HEALTHY
Status Change:  1 day ago

Component      Status        Status Change     Reasons & Notices
----------------------------------------------------------------
GPFS           HEALTHY       1 day ago         -
GUI            HEALTHY       1 day ago         -
NETWORK        HEALTHY       9 days ago        -
FILESYSTEM     HEALTHY       9 days ago        -
NOOBAA         HEALTHY       26 min. ago       -
PERFMON        HEALTHY       1 day ago         -
THRESHOLD      HEALTHY       9 days ago        -
sh-4.4# set -o vi
sh-4.4# mmhealth node show -N all

Node name:      master0-daemon
Node status:    FAILED
Status Change:  36 min. ago

Component      Status        Status Change     Reasons & Notices
--------------------------------------------------------------------------------
GPFS           FAILED        36 min. ago       gpfs_down, quorum_down
NETWORK        HEALTHY       1 day ago         -
FILESYSTEM     DEPEND        36 min. ago       unmounted_fs_check(remote-sample)
PERFMON        HEALTHY       1 day ago         -
THRESHOLD      HEALTHY       1 day ago         -

Node name:      master1-daemon
Node status:    HEALTHY
Status Change:  1 day ago

Component      Status        Status Change     Reasons & Notices
----------------------------------------------------------------
GPFS           HEALTHY       1 day ago         -
GUI            HEALTHY       1 day ago         -
NETWORK        HEALTHY       9 days ago        -
FILESYSTEM     HEALTHY       9 days ago        -
NOOBAA         HEALTHY       27 min. ago       -
PERFMON        HEALTHY       1 day ago         -
THRESHOLD      HEALTHY       9 days ago        -

Node name:      master2-daemon
Node status:    HEALTHY
Status Change:  1 day ago

Component       Status        Status Change     Reasons & Notices
-----------------------------------------------------------------
CALLHOME        HEALTHY       9 days ago        -
GPFS            HEALTHY       1 day ago         -
NETWORK         HEALTHY       9 days ago        -
FILESYSTEM      HEALTHY       9 days ago        -
GUI             HEALTHY       3 days ago        -
HEALTHCHECK     HEALTHY       9 days ago        -
PERFMON         HEALTHY       9 days ago        -
THRESHOLD       HEALTHY       9 days ago        -

Something is obviously hung in the PUT connection but logs and noobaa health don’t point to anything. When we issue mmstartup the PUT’s still fail. The only way to recover is to delete the Noobaa endpoint pods and have new ones generated again.

I have been able to recreate this very easily so if it is required I can set this up on my test stand

Expected behavior

1.When doing mmshutdown on one node, it should not impact cluster wide I/O capability. It should not be an outage. If indeed an outage is expected, then mmstartup should recover I/O capability.

Steps to reproduce

  1. Start a cosbench run. I can provide the xml if needed. Once I/O is running, issue mmshutdown from within one CNSA Ibm Spectrum Scale core pod.

More information - Screenshots / Logs / Other output

Must gather and noobaa diagnose in https://ibm.ent.box.com/folder/145794528783?s=uueh7fp424vxs2bt4ndrnvh7uusgu6tocd

This issue started as HPO https://github.ibm.com/IBMSpectrumScale/hpo-core/issues/659 Screeners determined that it was with Nooobaa. I have also slacked the CNSA team for input but have not heard back.

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Comments: 51 (30 by maintainers)

Most upvoted comments

I tested the patch today and it works. I no longer see the issue. Thank you.

When files are size 100 - 200 MB the condition does not occur. This defect does not happen.

When files are size 3 - 4 Gig, No files get completly written:

[root@c83f1-ems s5003]# find ./s500* -type f  | wc -l
29
[root@c83f1-ems s5003]# find ./s500* -type f
./s5003b1/.noobaa-nsfs_625d97a99e2004002a837889/uploads/9c126154-32de-4353-9b0f-abe54be1d09b
./s5003b2/.noobaa-nsfs_625d97b29e2004002a83788c/uploads/bcc7e25a-b0ee-441c-9ecc-2a410ae8f5d0
./s5003b2/.noobaa-nsfs_625d97b29e2004002a83788c/uploads/04daf916-1cee-46d1-842a-4edfae8413c6
./s5003b3/alias_commands
./s5003b5/.noobaa-nsfs_625d97be9e2004002a837895/uploads/1067f77d-96fd-42e1-9f7a-367f76d3fa54
./s5003b5/.noobaa-nsfs_625d97be9e2004002a837895/uploads/4ea1ea57-23f7-4188-a3b6-659c48c6d70d
./s5003b5/.noobaa-nsfs_625d97be9e2004002a837895/uploads/d04bfa57-eb67-4cc4-8ff8-46269272c90d
./s5003b5/.noobaa-nsfs_625d97be9e2004002a837895/uploads/3e26e3f4-6be8-42f7-aa63-ac8f7465b44d
./s5003b5/.noobaa-nsfs_625d97be9e2004002a837895/uploads/e6f23316-8bad-44be-96ff-0e7a4a739a6c
./s5003b5/.noobaa-nsfs_625d97be9e2004002a837895/uploads/715ec2bf-f681-4442-b38a-3e9582f83d0b
./s5003b5/.noobaa-nsfs_625d97be9e2004002a837895/uploads/f9cc167f-6c18-4900-bceb-0c5f0d403747
./s5003b5/.noobaa-nsfs_625d97be9e2004002a837895/uploads/3ad611f7-adeb-49db-aae6-3a4221283976
./s5003b5/.noobaa-nsfs_625d97be9e2004002a837895/uploads/5478b862-1ee6-42e3-9b2a-a17e16e8339b
./s5003b5/.noobaa-nsfs_625d97be9e2004002a837895/uploads/62dd5cae-03b4-425f-af14-aa1b117a73ab
./s5003b5/.noobaa-nsfs_625d97be9e2004002a837895/uploads/b3c2c524-b175-4f49-830c-fc1cabeba17a
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/27e34e18-8cba-44cc-ae60-2f10f3e49adf
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/e45d4c30-c1fc-4e0b-aada-788677f81f9c
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/9c19f8b5-e4c2-43c8-a136-f57f43d6c89d
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/d23fdefa-01c0-49d3-869b-9bd41f3b70cb
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/01bae4e3-65e7-4cd6-a7dd-cf2abaa67ff3
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/01a827ba-5f02-4bdf-bf3b-b1d3c185a6c8
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/928776f9-2787-4ab9-83c2-38c9c1f7a1a5
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/9f7b7aae-9c9c-4bcf-a5ca-208f194b9a61
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/b68acdbb-8b0d-4d20-be2f-01905b834163
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/be4e8952-8e02-4711-aafc-b2dc5866b92a
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/8a6ae8b8-78f2-4648-b77a-67820fd95575
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/8b718d29-d288-4d27-855c-d87e5af2dad4
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/925939f7-bf58-4cc3-9987-a1618f0deff1
./s5003b6/.noobaa-nsfs_625d97c19e2004002a837898/uploads/de49df27-eff6-4683-8d8b-43030c220912
[root@c83f1-ems s5003]#

The cosbench log:

================================================== stage: s1-prepare_rGB ==================================================
---------------------------------- mission: M4432CA8957, driver: dan4 ----------------------------------
2022-04-19 14:54:02,009 [INFO] [Log4jLogManager] - will append log to file /root/cosbench/log/mission/M4432CA8957.log
2022-04-19 14:54:02,277 [INFO] [NoneStorage] - performing PUT at /s5003b1/s5003o3_rGB
2022-04-19 14:54:02,277 [INFO] [NoneStorage] - performing PUT at /s5003b1/s5003o1_rGB
2022-04-19 14:54:02,278 [INFO] [NoneStorage] - performing PUT at /s5003b1/s5003o2_rGB
2022-04-19 14:54:02,311 [ERROR] [AbstractOperator] - worker 2 fail to perform operation s5003b1/s5003o2_rGB
java.lang.ArrayIndexOutOfBoundsException
	at com.intel.cosbench.driver.generator.RandomInputStream.processBytes(RandomInputStream.java:106)
	at org.apache.commons.io.input.NullInputStream.read(NullInputStream.java:232)
	at org.apache.commons.io.input.ProxyInputStream.read(ProxyInputStream.java:75)
	at org.apache.commons.io.input.CountingInputStream.read(CountingInputStream.java:74)
	at com.intel.cosbench.driver.generator.XferCountingInputStream.read(XferCountingInputStream.java:38)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.util.LengthCheckInputStream.read(LengthCheckInputStream.java:108)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.services.s3.internal.MD5DigestCalculatingInputStream.read(MD5DigestCalculatingInputStream.java:98)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.event.ProgressInputStream.read(ProgressInputStream.java:151)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at org.apache.http.entity.InputStreamEntity.writeTo(InputStreamEntity.java:138)
	at com.amazonaws.http.RepeatableInputStreamRequestEntity.writeTo(RepeatableInputStreamRequestEntity.java:153)
	at org.apache.http.entity.HttpEntityWrapper.writeTo(HttpEntityWrapper.java:89)
	at org.apache.http.impl.client.EntityEnclosingRequestWrapper$EntityWrapper.writeTo(EntityEnclosingRequestWrapper.java:108)
	at org.apache.http.impl.entity.EntitySerializer.serialize(EntitySerializer.java:117)
	at org.apache.http.impl.AbstractHttpClientConnection.sendRequestEntity(AbstractHttpClientConnection.java:265)
	at org.apache.http.impl.conn.ManagedClientConnectionImpl.sendRequestEntity(ManagedClientConnectionImpl.java:203)
	at org.apache.http.protocol.HttpRequestExecutor.doSendRequest(HttpRequestExecutor.java:236)
	at com.amazonaws.http.protocol.SdkHttpRequestExecutor.doSendRequest(SdkHttpRequestExecutor.java:63)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:121)
	at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:685)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:487)
	at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:863)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
	at com.amazonaws.http.AmazonHttpClient.executeOneRequest(AmazonHttpClient.java:837)
	at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:607)
	at com.amazonaws.http.AmazonHttpClient.doExecute(AmazonHttpClient.java:376)
	at com.amazonaws.http.AmazonHttpClient.executeWithTimer(AmazonHttpClient.java:338)
	at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:287)
	at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:3826)
	at com.amazonaws.services.s3.AmazonS3Client.putObject(AmazonS3Client.java:1405)
	at com.amazonaws.services.s3.AmazonS3Client.putObject(AmazonS3Client.java:1270)
	at com.intel.cosbench.api.S3Stor.S3Storage.createObject(S3Storage.java:167)
	at com.intel.cosbench.driver.operator.Writer.doWrite(Writer.java:98)
	at com.intel.cosbench.driver.operator.Preparer.operate(Preparer.java:97)
	at com.intel.cosbench.driver.operator.AbstractOperator.operate(AbstractOperator.java:76)
	at com.intel.cosbench.driver.agent.WorkAgent.performOperation(WorkAgent.java:197)
	at com.intel.cosbench.driver.agent.WorkAgent.doWork(WorkAgent.java:177)
	at com.intel.cosbench.driver.agent.WorkAgent.execute(WorkAgent.java:134)
	at com.intel.cosbench.driver.agent.AbstractAgent.call(AbstractAgent.java:44)
	at com.intel.cosbench.driver.agent.AbstractAgent.call(AbstractAgent.java:1)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
2022-04-19 14:54:02,315 [INFO] [NoneStorage] - performing PUT at /s5003b2/s5003o2_rGB
2022-04-19 14:54:02,315 [INFO] [NoneStorage] - performing PUT at /s5003b2/s5003o1_rGB
2022-04-19 14:54:02,315 [INFO] [NoneStorage] - performing PUT at /s5003b2/s5003o3_rGB
2022-04-19 14:54:02,318 [ERROR] [ErrorStatistics] - error code: N/A occurred 7 times, fail to operate: s5003b1/s5003o2_rGB, s5003b1/s5003o2_rGB, s5003b1/s5003o3_rGB, s5003b1/s5003o1_rGB, s5003b2/s5003o2_rGB, s5003b2/s5003o1_rGB, s5003b2/s5003o3_rGB
java.lang.ArrayIndexOutOfBoundsException
	at com.intel.cosbench.driver.generator.RandomInputStream.processBytes(RandomInputStream.java:106)
	at org.apache.commons.io.input.NullInputStream.read(NullInputStream.java:232)
	at org.apache.commons.io.input.ProxyInputStream.read(ProxyInputStream.java:75)
	at org.apache.commons.io.input.CountingInputStream.read(CountingInputStream.java:74)
	at com.intel.cosbench.driver.generator.XferCountingInputStream.read(XferCountingInputStream.java:38)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.util.LengthCheckInputStream.read(LengthCheckInputStream.java:108)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.services.s3.internal.MD5DigestCalculatingInputStream.read(MD5DigestCalculatingInputStream.java:98)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.event.ProgressInputStream.read(ProgressInputStream.java:151)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at org.apache.http.entity.InputStreamEntity.writeTo(InputStreamEntity.java:138)
	at com.amazonaws.http.RepeatableInputStreamRequestEntity.writeTo(RepeatableInputStreamRequestEntity.java:153)
	at org.apache.http.entity.HttpEntityWrapper.writeTo(HttpEntityWrapper.java:89)
	at org.apache.http.impl.client.EntityEnclosingRequestWrapper$EntityWrapper.writeTo(EntityEnclosingRequestWrapper.java:108)
	at org.apache.http.impl.entity.EntitySerializer.serialize(EntitySerializer.java:117)
	at org.apache.http.impl.AbstractHttpClientConnection.sendRequestEntity(AbstractHttpClientConnection.java:265)
	at org.apache.http.impl.conn.ManagedClientConnectionImpl.sendRequestEntity(ManagedClientConnectionImpl.java:203)
	at org.apache.http.protocol.HttpRequestExecutor.doSendRequest(HttpRequestExecutor.java:236)
	at com.amazonaws.http.protocol.SdkHttpRequestExecutor.doSendRequest(SdkHttpRequestExecutor.java:63)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:121)
	at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:685)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:487)
	at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:863)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
	at com.amazonaws.http.AmazonHttpClient.executeOneRequest(AmazonHttpClient.java:837)
	at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:607)
	at com.amazonaws.http.AmazonHttpClient.doExecute(AmazonHttpClient.java:376)
	at com.amazonaws.http.AmazonHttpClient.executeWithTimer(AmazonHttpClient.java:338)
	at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:287)
	at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:3826)
	at com.amazonaws.services.s3.AmazonS3Client.putObject(AmazonS3Client.java:1405)
	at com.amazonaws.services.s3.AmazonS3Client.putObject(AmazonS3Client.java:1270)
	at com.intel.cosbench.api.S3Stor.S3Storage.createObject(S3Storage.java:167)
	at com.intel.cosbench.driver.operator.Writer.doWrite(Writer.java:98)
	at com.intel.cosbench.driver.operator.Preparer.operate(Preparer.java:97)
	at com.intel.cosbench.driver.operator.AbstractOperator.operate(AbstractOperator.java:76)
	at com.intel.cosbench.driver.agent.WorkAgent.performOperation(WorkAgent.java:197)
	at com.intel.cosbench.driver.agent.WorkAgent.doWork(WorkAgent.java:177)
	at com.intel.cosbench.driver.agent.WorkAgent.execute(WorkAgent.java:134)
	at com.intel.cosbench.driver.agent.AbstractAgent.call(AbstractAgent.java:44)
	at com.intel.cosbench.driver.agent.AbstractAgent.call(AbstractAgent.java:1)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
---------------------------------- mission: ME432CA896C, driver: app7 ----------------------------------
2022-04-19 14:54:02,007 [INFO] [Log4jLogManager] - will append log to file /root/cosbench/log/mission/ME432CA896C.log
================================================== stage: s2-rGB_write_read_delete ==================================================
---------------------------------- mission: MB432CD6741, driver: dan4 ----------------------------------
2022-04-19 14:54:14,007 [INFO] [Log4jLogManager] - will append log to file /root/cosbench/log/mission/MB432CD6741.log
2022-04-19 14:54:14,272 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,278 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,280 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,280 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o2_rGB
2022-04-19 14:54:14,279 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,277 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,282 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,282 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,282 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o9_rGB
2022-04-19 14:54:14,277 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,277 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,276 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o1_rGB
2022-04-19 14:54:14,283 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,275 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,275 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,286 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o13_rGB
2022-04-19 14:54:14,287 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,274 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,274 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,287 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,288 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,274 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,288 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o17_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,274 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o2_rGB
2022-04-19 14:54:14,290 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,290 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,290 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,290 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o3_rGB
2022-04-19 14:54:14,274 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,291 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,272 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,292 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,272 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,270 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,272 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,292 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,292 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o4_rGB
2022-04-19 14:54:14,292 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,292 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,291 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,291 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,291 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,291 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,291 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,291 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,291 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,291 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,291 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,290 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,290 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,290 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,290 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,290 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,290 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,290 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,290 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o1_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o20_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o19_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o18_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,289 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,288 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,288 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,288 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,288 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,288 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,288 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,288 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,288 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,288 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o16_rGB
2022-04-19 14:54:14,287 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,287 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,287 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,287 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,287 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,287 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,287 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o15_rGB
2022-04-19 14:54:14,287 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,286 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o14_rGB
2022-04-19 14:54:14,286 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,286 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,286 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o12_rGB
2022-04-19 14:54:14,284 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o11_rGB
2022-04-19 14:54:14,284 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,284 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,284 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,284 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,283 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o10_rGB
2022-04-19 14:54:14,283 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,283 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,283 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,283 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,283 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,283 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,283 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,283 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,283 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,283 [ERROR] [AbstractOperator] - worker 18 fail to perform operation s5003b6/s5003o2_rGB
java.lang.ArrayIndexOutOfBoundsException
	at com.intel.cosbench.driver.generator.RandomInputStream.processBytes(RandomInputStream.java:106)
	at org.apache.commons.io.input.NullInputStream.read(NullInputStream.java:232)
	at org.apache.commons.io.input.ProxyInputStream.read(ProxyInputStream.java:75)
	at org.apache.commons.io.input.CountingInputStream.read(CountingInputStream.java:74)
	at com.intel.cosbench.driver.generator.XferCountingInputStream.read(XferCountingInputStream.java:38)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.util.LengthCheckInputStream.read(LengthCheckInputStream.java:108)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.services.s3.internal.MD5DigestCalculatingInputStream.read(MD5DigestCalculatingInputStream.java:98)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.event.ProgressInputStream.read(ProgressInputStream.java:151)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at org.apache.http.entity.InputStreamEntity.writeTo(InputStreamEntity.java:138)
	at com.amazonaws.http.RepeatableInputStreamRequestEntity.writeTo(RepeatableInputStreamRequestEntity.java:153)
	at org.apache.http.entity.HttpEntityWrapper.writeTo(HttpEntityWrapper.java:89)
	at org.apache.http.impl.client.EntityEnclosingRequestWrapper$EntityWrapper.writeTo(EntityEnclosingRequestWrapper.java:108)
	at org.apache.http.impl.entity.EntitySerializer.serialize(EntitySerializer.java:117)
	at org.apache.http.impl.AbstractHttpClientConnection.sendRequestEntity(AbstractHttpClientConnection.java:265)
	at org.apache.http.impl.conn.ManagedClientConnectionImpl.sendRequestEntity(ManagedClientConnectionImpl.java:203)
	at org.apache.http.protocol.HttpRequestExecutor.doSendRequest(HttpRequestExecutor.java:236)
	at com.amazonaws.http.protocol.SdkHttpRequestExecutor.doSendRequest(SdkHttpRequestExecutor.java:63)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:121)
	at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:685)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:487)
	at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:863)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
	at com.amazonaws.http.AmazonHttpClient.executeOneRequest(AmazonHttpClient.java:837)
	at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:607)
	at com.amazonaws.http.AmazonHttpClient.doExecute(AmazonHttpClient.java:376)
	at com.amazonaws.http.AmazonHttpClient.executeWithTimer(AmazonHttpClient.java:338)
	at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:287)
	at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:3826)
	at com.amazonaws.services.s3.AmazonS3Client.putObject(AmazonS3Client.java:1405)
	at com.amazonaws.services.s3.AmazonS3Client.putObject(AmazonS3Client.java:1270)
	at com.intel.cosbench.api.S3Stor.S3Storage.createObject(S3Storage.java:167)
	at com.intel.cosbench.driver.operator.Writer.doWrite(Writer.java:98)
	at com.intel.cosbench.driver.operator.Writer.operate(Writer.java:79)
	at com.intel.cosbench.driver.operator.AbstractOperator.operate(AbstractOperator.java:76)
	at com.intel.cosbench.driver.agent.WorkAgent.performOperation(WorkAgent.java:197)
	at com.intel.cosbench.driver.agent.WorkAgent.doWork(WorkAgent.java:177)
	at com.intel.cosbench.driver.agent.WorkAgent.execute(WorkAgent.java:134)
	at com.intel.cosbench.driver.agent.AbstractAgent.call(AbstractAgent.java:44)
	at com.intel.cosbench.driver.agent.AbstractAgent.call(AbstractAgent.java:1)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
2022-04-19 14:54:14,339 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,282 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,340 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o5_rGB
2022-04-19 14:54:14,340 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,282 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,282 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,282 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,282 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o8_rGB
2022-04-19 14:54:14,282 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,282 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,282 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,281 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o7_rGB
2022-04-19 14:54:14,281 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,281 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o6_rGB
2022-04-19 14:54:14,281 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,281 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o5_rGB
2022-04-19 14:54:14,281 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,281 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,281 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,281 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,280 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,280 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o4_rGB
2022-04-19 14:54:14,280 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,280 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,280 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o3_rGB
2022-04-19 14:54:14,347 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,346 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o8_rGB
2022-04-19 14:54:14,345 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o7_rGB
2022-04-19 14:54:14,343 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,341 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,340 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,340 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,352 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,340 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o6_rGB
2022-04-19 14:54:14,340 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,340 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,340 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,340 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,340 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,340 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,340 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,339 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,339 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,339 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,339 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,339 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,354 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,352 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,351 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,350 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
---------------------------------- mission: M7432CD676E, driver: app7 ----------------------------------
2022-04-19 14:54:14,007 [INFO] [Log4jLogManager] - will append log to file /root/cosbench/log/mission/M7432CD676E.log
2022-04-19 14:54:14,244 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o5_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o7_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o8_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o1_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o13_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,246 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o2_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o6_rGB
2022-04-19 14:54:14,251 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,251 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o10_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,245 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,245 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,251 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,251 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,251 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,251 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o9_rGB
2022-04-19 14:54:14,251 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,251 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o8_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o7_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o5_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o4_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o3_rGB
2022-04-19 14:54:14,250 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,249 [ERROR] [AbstractOperator] - worker 189 fail to perform operation s5003b5/s5003o13_rGB
java.lang.ArrayIndexOutOfBoundsException
	at com.intel.cosbench.driver.generator.RandomInputStream.processBytes(RandomInputStream.java:106)
	at org.apache.commons.io.input.NullInputStream.read(NullInputStream.java:232)
	at org.apache.commons.io.input.ProxyInputStream.read(ProxyInputStream.java:75)
	at org.apache.commons.io.input.CountingInputStream.read(CountingInputStream.java:74)
	at com.intel.cosbench.driver.generator.XferCountingInputStream.read(XferCountingInputStream.java:38)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.util.LengthCheckInputStream.read(LengthCheckInputStream.java:108)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.services.s3.internal.MD5DigestCalculatingInputStream.read(MD5DigestCalculatingInputStream.java:98)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at com.amazonaws.event.ProgressInputStream.read(ProgressInputStream.java:151)
	at com.amazonaws.internal.SdkFilterInputStream.read(SdkFilterInputStream.java:72)
	at org.apache.http.entity.InputStreamEntity.writeTo(InputStreamEntity.java:138)
	at com.amazonaws.http.RepeatableInputStreamRequestEntity.writeTo(RepeatableInputStreamRequestEntity.java:153)
	at org.apache.http.entity.HttpEntityWrapper.writeTo(HttpEntityWrapper.java:89)
	at org.apache.http.impl.client.EntityEnclosingRequestWrapper$EntityWrapper.writeTo(EntityEnclosingRequestWrapper.java:108)
	at org.apache.http.impl.entity.EntitySerializer.serialize(EntitySerializer.java:117)
	at org.apache.http.impl.AbstractHttpClientConnection.sendRequestEntity(AbstractHttpClientConnection.java:265)
	at org.apache.http.impl.conn.ManagedClientConnectionImpl.sendRequestEntity(ManagedClientConnectionImpl.java:203)
	at org.apache.http.protocol.HttpRequestExecutor.doSendRequest(HttpRequestExecutor.java:236)
	at com.amazonaws.http.protocol.SdkHttpRequestExecutor.doSendRequest(SdkHttpRequestExecutor.java:63)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:121)
	at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:685)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:487)
	at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:863)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
	at com.amazonaws.http.AmazonHttpClient.executeOneRequest(AmazonHttpClient.java:837)
	at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:607)
	at com.amazonaws.http.AmazonHttpClient.doExecute(AmazonHttpClient.java:376)
	at com.amazonaws.http.AmazonHttpClient.executeWithTimer(AmazonHttpClient.java:338)
	at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:287)
	at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:3826)
	at com.amazonaws.services.s3.AmazonS3Client.putObject(AmazonS3Client.java:1405)
	at com.amazonaws.services.s3.AmazonS3Client.putObject(AmazonS3Client.java:1270)
	at com.intel.cosbench.api.S3Stor.S3Storage.createObject(S3Storage.java:167)
	at com.intel.cosbench.driver.operator.Writer.doWrite(Writer.java:98)
	at com.intel.cosbench.driver.operator.Writer.operate(Writer.java:79)
	at com.intel.cosbench.driver.operator.AbstractOperator.operate(AbstractOperator.java:76)
	at com.intel.cosbench.driver.agent.WorkAgent.performOperation(WorkAgent.java:197)
	at com.intel.cosbench.driver.agent.WorkAgent.doWork(WorkAgent.java:177)
	at com.intel.cosbench.driver.agent.WorkAgent.execute(WorkAgent.java:134)
	at com.intel.cosbench.driver.agent.AbstractAgent.call(AbstractAgent.java:44)
	at com.intel.cosbench.driver.agent.AbstractAgent.call(AbstractAgent.java:1)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,253 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o1_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o20_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o19_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o18_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o17_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,249 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o16_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o15_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o14_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o12_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o11_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o10_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o9_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,248 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o6_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o4_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o3_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o2_rGB
2022-04-19 14:54:14,247 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,258 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,256 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,256 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o16_rGB
2022-04-19 14:54:14,256 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,256 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,259 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,255 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,255 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o15_rGB
2022-04-19 14:54:14,255 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,255 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,254 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,254 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o14_rGB
2022-04-19 14:54:14,254 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,254 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o13_rGB
2022-04-19 14:54:14,254 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o12_rGB
2022-04-19 14:54:14,254 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,253 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,253 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,253 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,253 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,253 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o11_rGB
2022-04-19 14:54:14,253 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,253 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,253 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,253 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,253 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,253 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,260 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o2_rGB
2022-04-19 14:54:14,260 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o1_rGB
2022-04-19 14:54:14,259 [INFO] [NoneStorage] - performing PUT at /s5003b6/s5003o18_rGB
2022-04-19 14:54:14,259 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o3_rGB
2022-04-19 14:54:14,259 [INFO] [NoneStorage] - performing PUT at /s5003b5/s5003o17_rGB
2022-04-19 14:54:14,259 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB
2022-04-19 14:54:14,258 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,260 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o3_rGB
2022-04-19 14:54:14,261 [INFO] [NoneStorage] - performing GET at /s5003b1/s5003o1_rGB
2022-04-19 14:54:14,261 [INFO] [NoneStorage] - performing GET at /s5003b2/s5003o2_rGB

Did some follow-up investigation asked for by Romy. In the process, I have refined the trigger. So, in summary 5 things:

  1. Cosbench will give a java error when the cosbench xml file has hashcheck=true AND file sizes are 3gig or bigger. In some ways, I don’t consider this to be a noobaa problem . This is probably something with cosbench. When the java error occurs the file does not get sent. This can’t be noobaa’s fault. I don’t think we need to persue the java errors from cosbench. When files are 3 gig and bigger but hashCheck is not set everything works fine.

  2. Cosbench termination of workload or lettting it complete, w/out hashcheck=true AND 3 gig or bigger is OK. s3 cp file works
 and there are no java errors in the cosbench logs.

3. Cosbench w/ hashcheck=true AND files 1 - 2 Gig will causes s3 cp file to timeout. This is the error that this defect needs to persue. 4 . I checked to make sure that Cosbench is not holding the port open or blocked. I stopped cosbench on all drivers and still could not s3 cp file
. 5. If I remove the read from the Cosbench workload xml file, then s3 cp file will work. It appears to NOT be a function of file size but doing both reads (GET) and writes (PUT) with hashCheck=true .

The best xml file to reproduce this quickly is:

[root@c83f1-dan4 RW_workloads]# cat /root/cosbench/workloads/RW_workloads/rand_read_write_delete_GB_1hour/s5002_GB_random_size_num_of_objects.xml
<?xml version="1.0" encoding="UTF-8" ?>
<workload name="GBrandomsizenumobj" description="GBrandom read and write workload">
  <storage type="s3" config="accesskey=qiIImaITeJCdkdABWAsk;secretkey=c80yUC5QfG9sxK99XQI70zXjpin9cqIeSR54r47c;path_style_access=true;endpoint=http://metallb2:80"/>

  <workflow>

   <workstage name="prepare_rGB">
      <work name="prepare_rGB" workers="256" interval="10" rampup="0" type="prepare" ratio="100" config="cprefix=s5002b;oprefix=s5002o;osuffix=_rGB;containers=r(1,2);objects=r(1,3);sizes=r(1,2)GB;hashCheck=true"/>
    </workstage>

    <workstage name="rGB_write_read_delete">
      <work name="rGB_write_read_delete" workers="256" interval="10" rampup="0" runtime="300">
        <operation type="write" ratio="20" config="cprefix=s5002b;oprefix=s5002o;osuffix=_rGB;containers=r(5,6);objects=r(1,20);sizes=r(1,2)GB;hashCheck=true"/>
        <operation type="read" ratio="80" config="cprefix=s5002b;oprefix=s5002o;osuffix=_rGB;containers=r(1,2);objects=r(1,3);hashCheck=true"/>
      </work>
    </workstage>


  </workflow>
</workload>

One test was done with log level nsfs. Noobaa diagnose and must-gather are colllected and uploaded to our box note.

root@c83f1-dan4 RW_workloads]# date ; sh /root/cosbench/cli.sh submit /root/cosbench/workloads/RW_workloads/rand_read_write_delete_GB_1hour/s5002_GB_random_size_num_of_objects.xml
Wed Apr 13 15:34:25 EDT 2022
Accepted with ID: w967
[root@c83f1-dan4 RW_workloads]#




The hang occurred around
Wed Apr 13 15:36:10 EDT 2022 Grabbed logs

Now try a new file name

[root@c83f1-dan4 RW_workloads]# date; s5001_2_31 cp good.xml s3://s5001b1
Wed Apr 13 15:38:33 EDT 2022

NOW LOG LEVEL ALL

[root@c83f1-dan4 RW_workloads]# date ; sh /root/cosbench/cli.sh submit /root/cosbench/workloads/RW_workloads/rand_read_write_delete_GB_1hour/s5002_GB_random_size_num_of_objects.xml
Wed Apr 13 15:55:08 EDT 2022
Accepted with ID: w969

Now try to s3 cp a file

[root@c83f1-dan4 RW_workloads]# date; s5001_2_31 cp nohup.out s3://s5001b1
Wed Apr 13 15:56:12 EDT 2022
upload: ./nohup.out to s3://s5001b1/nohup.out
[root@c83f1-dan4 RW_workloads]# date; s5001_2_31 cp rand_read.xml s3://s5001b1
Wed Apr 13 15:57:02 EDT 2022

In all cases oc logs does not show any errors.