Pulsar: Error offloading:

[geyrix57]

I'm getting this error when trying to manually offload a topic to s3 bucket.

Broker config

managedLedgerOffloadDriver=aws-s3
s3ManagedLedgerOffloadRegion=us-west-2
s3ManagedLedgerOffloadBucket=mybucket
s3ManagedLedgerOffloadServiceEndpoint=https://mybucket.blabla.blabla.com/

Error

Reason: Error offloading: org.apache.bookkeeper.mledger.ManagedLedgerException: java.util.concurrent.CompletionException: org.jclouds.aws.AWSResponseException: request POST https://mybucket.blabla.blabla.com/mybucket/3aab7c02-81ab-470b-badb-7e4e5c74bb2d-ledger-19?uploads HTTP/1.1 failed with code 400, error: AWSError{requestId='....', requestToken='....', code='AuthorizationHeaderMalformed', message='The authorization header is malformed; the region 'us-east-1' is wrong; expecting 'us-west-2'', context='{Region=us-west-2, HostId=....}'}

It doesn't matter what region a use in s3ManagedLedgerOffloadRegion I'm always getting the same error. (the right region is us-west-2 as shown on the config)

System configuration

Pulsar version: 2.3.0

[jiazhai]

@geyrix57 , If you are using other blobstore provider rather than "aws-s3",
you should use config:

managedLedgerOffloadDriver=s3
s3ManagedLedgerOffloadBucket=mybucket
s3ManagedLedgerOffloadServiceEndpoint=https://mybucket.blabla.blabla.com/

Seems currently there was some regression. I am still trying to fix "s3" type. will update this issue once fixed.

[vicaya]

We ran into this issue in 2.4 as well. What's the current status/plan? Is this gonna be fixed in 2.4.1?

[jiazhai]

will check and handle this issue

[lukestephenson-zendesk]

Also seeing this with pulsar 2.5.1 trying to use a bucket in ap-southeast-2

[wolfstudy]

Also seeing this with pulsar 2.5.1 trying to use a bucket in ap-southeast-2

Thanks @lukestephenson-zendesk feedback, can you provide your configuration? If possible, you can also provide specific error information.

[wolfstudy]

@geyrix57

s3ManagedLedgerOffloadServiceEndpoint=https://mybucket.blabla.blabla.com/

The s3ManagedLedgerOffloadServiceEndpoint useful for testing, If you are using a real AWS-S3 bucket, you can not configure this option, reference to authentication-with-aws.

[dionjansen]

@wolfstudy I'm getting the same with pulsar 2.5.0 also I use a non-standard region eu-west-1

My pulsar config:

managedLedgerOffloadDriver: aws-s3
s3ManagedLedgerOffloadBucket: test-offload-bucket
s3ManagedLedgerOffloadRegion: eu-west-1

Broker logs:

15:23:53.548 [pulsar-io-24-1] INFO  org.apache.pulsar.broker.service.ServerCnx - [/192.168.183.79:49920][persistent://packhunt/tests/test-topic-1] Creating producer. producerId=0
15:23:53.549 [Thread-1050] INFO  org.apache.pulsar.broker.service.ServerCnx - [/192.168.183.79:49920] persistent://packhunt/tests/test-topic-1 configured with schema false
15:23:53.550 [Thread-1050] INFO  org.apache.pulsar.broker.service.ServerCnx - [/192.168.183.79:49920] Created new producer: Producer{topic=PersistentTopic{topic=persistent://packhunt/tests/test-topic-1}, client=/192.168.183.79:49920, producerName=pulsar-50-1007, producerId=0}
15:23:53.603 [bookkeeper-ml-workers-OrderedExecutor-7-0] INFO  org.apache.bookkeeper.mledger.impl.OpAddEntry - [packhunt/tests/persistent/test-topic-1] Closing ledger 2227 for being full
15:23:53.608 [bookkeeper-ml-workers-OrderedExecutor-7-0] INFO  org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [packhunt/tests/persistent/test-topic-1] Going to automatically offload ledgers [2215, 2216, 2217, 2218, 2219, 2220], total size = 3013527080, already offloaded = 0, to offload = 3010342423
15:23:53.608 [bookkeeper-ml-workers-OrderedExecutor-7-0] INFO  org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [packhunt/tests/persistent/test-topic-1] Preparing metadata to offload ledger 2215 with uuid b965b889-7202-4ada-9dd3-d9ce07b552d8
15:23:53.608 [bookkeeper-ml-workers-OrderedExecutor-7-0] INFO  org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [packhunt/tests/persistent/test-topic-1] Found previous offload attempt for ledger 2215, uuid b965b889-7202-4ada-9dd3-d9ce07b552d8, cleaning up
15:23:53.618 [pulsar-web-33-3] INFO  org.eclipse.jetty.server.RequestLog - 192.168.182.18 - - [16/Jun/2020:15:23:53 +0000] "GET /status.html HTTP/1.1" 200 2 "-" "kube-probe/1.14+" 0
15:23:53.618 [bookkeeper-ml-workers-OrderedExecutor-7-0] WARN  org.apache.bookkeeper.client.BookieWatcherImpl - New ensemble: [pulsar-bookie-3.pulsar-bookie.pulsar2.svc.cluster.local:3181, pulsar-bookie-2.pulsar-bookie.pulsar2.svc.cluster.local:3181, pulsar-bookie-0.pulsar-bookie.pulsar2.svc.cluster.local:3181] is not adhering to Placement Policy. quarantinedBookies: []
15:23:53.621 [pulsar-ordered-OrderedExecutor-5-0-EventThread] INFO  org.apache.pulsar.zookeeper.ZooKeeperCache - [State:CONNECTED Timeout:30000 sessionid:0x300000237e600ca local:/192.168.163.218:39918 remoteserver:pulsar-zookeeper/192.168.169.137:2181 lastZxid:4295194973 xid:14558 sent:14558 recv:15712 queuedpkts:0 pendingresp:0 queuedevents:0] Received ZooKeeper watch event: WatchedEvent state:SyncConnected type:NodeDataChanged path:/managed-ledgers/packhunt/tests/persistent/test-topic-1
15:23:53.621 [pulsar-ordered-OrderedExecutor-7-0-EventThread] INFO  org.apache.pulsar.zookeeper.ZooKeeperCache - [State:CONNECTED Timeout:30000 sessionid:0x200000249b200c4 local:/192.168.152.113:59370 remoteserver:pulsar-zookeeper/192.168.127.51:2181 lastZxid:4295194975 xid:15908 sent:15908 recv:17066 queuedpkts:0 pendingresp:1 queuedevents:1] Received ZooKeeper watch event: WatchedEvent state:SyncConnected type:NodeDataChanged path:/managed-ledgers/packhunt/tests/persistent/test-topic-1
15:23:53.621 [bookkeeper-ml-workers-OrderedExecutor-7-0] INFO  org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [packhunt/tests/persistent/test-topic-1] Metadata prepared for offload of ledger 2215 with uuid b965b889-7202-4ada-9dd3-d9ce07b552d8
15:23:53.621 [pulsar-ordered-OrderedExecutor-0-0-EventThread] INFO  org.apache.pulsar.zookeeper.ZooKeeperCache - [State:CONNECTED Timeout:30000 sessionid:0x100045f141f00d4 local:/192.168.191.251:40648 remoteserver:pulsar-zookeeper/192.168.129.222:2181 lastZxid:4295194973 xid:16249 sent:16249 recv:17421 queuedpkts:0 pendingresp:0 queuedevents:0] Received ZooKeeper watch event: WatchedEvent state:SyncConnected type:NodeDataChanged path:/managed-ledgers/packhunt/tests/persistent/test-topic-1
15:23:53.625 [pulsar-ordered-OrderedExecutor-7-0-EventThread] INFO  org.apache.bookkeeper.client.LedgerCreateOp - Ensemble: [pulsar-bookie-3.pulsar-bookie.pulsar2.svc.cluster.local:3181, pulsar-bookie-2.pulsar-bookie.pulsar2.svc.cluster.local:3181, pulsar-bookie-0.pulsar-bookie.pulsar2.svc.cluster.local:3181] for ledger: 2233
15:23:53.625 [pulsar-ordered-OrderedExecutor-7-0-EventThread] INFO  org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [packhunt/tests/persistent/test-topic-1] Created new ledger 2233
15:23:54.092 [offloader-OrderedScheduler-1-0] ERROR org.apache.bookkeeper.mledger.offload.jcloud.impl.BlobStoreManagedLedgerOffloader - Failed delete Blob
org.jclouds.aws.AWSResponseException: request POST https://test-offload-bucket.s3.amazonaws.com/?delete HTTP/1.1 failed with code 400, error: AWSError{requestId='031C5FE0A1D8315F', requestToken='F3G4gdz0gL7xFVMwIR1Dqcx+tNejlS7XeeRKc65VD6TpvCUYBeuPH5wOGmQHicUPZWchEhkihQQ=', code='AuthorizationHeaderMalformed', message='The authorization header is malformed; the region 'us-east-1' is wrong; expecting 'eu-west-1'', context='{Region=eu-west-1, HostId=F3G4gdz0gL7xFVMwIR1Dqcx+tNejlS7XeeRKc65VD6TpvCUYBeuPH5wOGmQHicUPZWchEhkihQQ=}'}
    at org.jclouds.aws.handlers.ParseAWSErrorFromXmlContent.handleError(ParseAWSErrorFromXmlContent.java:75) ~[?:?]
    at org.jclouds.http.handlers.DelegatingErrorHandler.handleError(DelegatingErrorHandler.java:65) ~[?:?]
    at org.jclouds.http.internal.BaseHttpCommandExecutorService.shouldContinue(BaseHttpCommandExecutorService.java:138) ~[?:?]
    at org.jclouds.http.internal.BaseHttpCommandExecutorService.invoke(BaseHttpCommandExecutorService.java:107) ~[?:?]
    at org.jclouds.rest.internal.InvokeHttpMethod.invoke(InvokeHttpMethod.java:91) ~[?:?]
    at org.jclouds.rest.internal.InvokeHttpMethod.apply(InvokeHttpMethod.java:74) ~[?:?]
    at org.jclouds.rest.internal.InvokeHttpMethod.apply(InvokeHttpMethod.java:45) ~[?:?]
    at org.jclouds.rest.internal.DelegatesToInvocationFunction.handle(DelegatesToInvocationFunction.java:156) ~[?:?]
    at org.jclouds.rest.internal.DelegatesToInvocationFunction.invoke(DelegatesToInvocationFunction.java:123) ~[?:?]
    at com.sun.proxy.$Proxy67.deleteObjects(Unknown Source) ~[?:?]
    at org.jclouds.s3.blobstore.S3BlobStore.removeBlobs(S3BlobStore.java:343) ~[?:?]
    at org.apache.bookkeeper.mledger.offload.jcloud.impl.BlobStoreManagedLedgerOffloader.lambda$deleteOffloaded$6(BlobStoreManagedLedgerOffloader.java:575) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_232]
    at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:125) [com.google.guava-guava-25.1-jre.jar:?]
    at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:57) [com.google.guava-guava-25.1-jre.jar:?]
    at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:78) [com.google.guava-guava-25.1-jre.jar:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_232]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_232]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_232]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_232]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_232]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_232]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.43.Final.jar:4.1.43.Final]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_232]
15:23:54.100 [bookkeeper-ml-scheduler-OrderedScheduler-7-0] WARN  org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Error cleaning up offload for 2215, (cleanup reason: Previous failed offload)
org.jclouds.aws.AWSResponseException: request POST https://test-offload-bucket.s3.amazonaws.com/?delete HTTP/1.1 failed with code 400, error: AWSError{requestId='031C5FE0A1D8315F', requestToken='F3G4gdz0gL7xFVMwIR1Dqcx+tNejlS7XeeRKc65VD6TpvCUYBeuPH5wOGmQHicUPZWchEhkihQQ=', code='AuthorizationHeaderMalformed', message='The authorization header is malformed; the region 'us-east-1' is wrong; expecting 'eu-west-1'', context='{Region=eu-west-1, HostId=F3G4gdz0gL7xFVMwIR1Dqcx+tNejlS7XeeRKc65VD6TpvCUYBeuPH5wOGmQHicUPZWchEhkihQQ=}'}
    at org.jclouds.aws.handlers.ParseAWSErrorFromXmlContent.handleError(ParseAWSErrorFromXmlContent.java:75) ~[?:?]
    at org.jclouds.http.handlers.DelegatingErrorHandler.handleError(DelegatingErrorHandler.java:65) ~[?:?]
    at org.jclouds.http.internal.BaseHttpCommandExecutorService.shouldContinue(BaseHttpCommandExecutorService.java:138) ~[?:?]
    at org.jclouds.http.internal.BaseHttpCommandExecutorService.invoke(BaseHttpCommandExecutorService.java:107) ~[?:?]
    at org.jclouds.rest.internal.InvokeHttpMethod.invoke(InvokeHttpMethod.java:91) ~[?:?]
    at org.jclouds.rest.internal.InvokeHttpMethod.apply(InvokeHttpMethod.java:74) ~[?:?]
    at org.jclouds.rest.internal.InvokeHttpMethod.apply(InvokeHttpMethod.java:45) ~[?:?]
    at org.jclouds.rest.internal.DelegatesToInvocationFunction.handle(DelegatesToInvocationFunction.java:156) ~[?:?]
    at org.jclouds.rest.internal.DelegatesToInvocationFunction.invoke(DelegatesToInvocationFunction.java:123) ~[?:?]
    at com.sun.proxy.$Proxy67.deleteObjects(Unknown Source) ~[?:?]
    at org.jclouds.s3.blobstore.S3BlobStore.removeBlobs(S3BlobStore.java:343) ~[?:?]
    at org.apache.bookkeeper.mledger.offload.jcloud.impl.BlobStoreManagedLedgerOffloader.lambda$deleteOffloaded$6(BlobStoreManagedLedgerOffloader.java:575) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_232]
    at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:125) ~[com.google.guava-guava-25.1-jre.jar:?]
    at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:57) ~[com.google.guava-guava-25.1-jre.jar:?]
    at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:78) ~[com.google.guava-guava-25.1-jre.jar:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_232]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_232]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_232]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_232]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_232]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_232]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-common-4.1.43.Final.jar:4.1.43.Final]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_232]

[milos-matijasevic]

There is thread in slack channel for same issue https://apache-pulsar.slack.com/archives/C5Z4T36F7/p1601393534056700
It depends on other configs, but maybe it can help you
In short try:

• s3ManagedLedgerOffloadServiceEndpoint: https://s3.YOUR_REGION.amazonaws.com
• If your cluster is running on AWS allow the IAM policy you are running as to do GetBucketLocation

[lukestephenson-zendesk]

Another related slack thread with the same issue https://apache-pulsar.slack.com/archives/C5Z4T36F7/p1591968316415200?thread_ts=1591924819.402800&cid=C5Z4T36F7

[yanirj]

There is thread in slack channel for same issue https://apache-pulsar.slack.com/archives/C5Z4T36F7/p1601393534056700
It depends on other configs, but maybe it can help you
In short try:

* `s3ManagedLedgerOffloadServiceEndpoint: https://s3.YOUR_REGION.amazonaws.com`

* If your cluster is running on AWS allow the IAM policy you are running as to do `GetBucketLocation`

I can confirm I had the exact same issue and adding permissions for GetBucketLocation solved it.

[codelipenghui]

Cool @yanirj. Looks like it's related to the configurations of the s3. So I will close this first and feel free to reopen it if needed.

[lukestephenson-zendesk]

I don't think this should have been closed. Yes it is related to the configuration of pulsar / S3, but the fact the pulsar logs don't indicate the problem correctly make it almost impossible to debug.