2020-09-14 11:46:25 UTC - Penghui Li: No, the broker does not send message to other consumers. By default, the consumers under the key_shared subscription will cover the whole key hash range, so the broker can always find the right consumer for the key. If the consumer with a fixed key hash range, you must ensure your consumers can cover the whole key hash range, otherwise the broker will stop dispatch messages. ---- 2020-09-14 11:49:07 UTC - Penghui Li: No, I’m not sure if there are contributors familiar with Neo4j, If you are familiar with Neo4j, You are welcome to add this feature ---- 2020-09-14 11:58:56 UTC - Ayaz Agayev: @Ayaz Agayev has joined the channel ---- 2020-09-14 12:51:10 UTC - Danilo Moreira: We figured out that this problem was due the size of the disk. We were using a NFS with 8EB. When Bookkeeper tries to get the total space of the disk, it can't read the real value. `long totalSpace = dir.getTotalSpace(); //this gets -9223372036854775808` When we reduced the size of the disk, everything worked fine. ---- 2020-09-14 15:35:24 UTC - Enrico: @Enrico has joined the channel ---- 2020-09-14 15:36:40 UTC - Enrico: Hello ---- 2020-09-14 16:30:56 UTC - Evan Furman: ---- 2020-09-14 16:35:17 UTC - Evan Furman: ---- 2020-09-14 16:35:53 UTC - Evan Furman: ---- 2020-09-14 16:40:13 UTC - Josh Perryman: @Josh Perryman has joined the channel ---- 2020-09-14 16:55:17 UTC - Addison Higham: good to know, meant to follow up here but didn't get a chance yet :slightly_smiling_face: ---- 2020-09-14 17:50:06 UTC - Raman Gupta: Thanks for the update @Addison Higham. That is definitely a limitation its well worth to be aware of. ---- 2020-09-14 18:19:03 UTC - Addison Higham: apologies for the misinformation the first time and we are always looking for use cases for why we have these features, if there isn't already, you might consider adding a feature request as a github issues for this ---- 2020-09-14 18:20:59 UTC - Raman Gupta: Sure. This one is fairly obvious from a use case perspective though -- if you want to support ordered consumption of messages (and Pulsar does / certainly wants to based on its current feature set), and if you want to support changing the number of partitions in a topic (which Pulsar does as well), then being able to support both features together is simply a logical consequence. ---- 2020-09-14 18:27:49 UTC - Addison Higham: certainly true, as mentioned previously, this is already a known improvement that has been discussed, but it can be helpful to have a member of the community get the discussion started on that +1 : Raman Gupta ---- 2020-09-14 18:31:24 UTC - Raman Gupta: I'm apparently confused about how peek works. I see a topic subscription with 13 items on its backlog. I run a `peek` command and get 13 ids: ```Batch Message ID: 627:129:0 Batch Message ID: 635:0:0 Batch Message ID: 635:1:0 Batch Message ID: 635:2:0 Batch Message ID: 635:3:0 Batch Message ID: 635:4:0 Batch Message ID: 635:5:0 Batch Message ID: 635:6:0 Batch Message ID: 635:7:0 Batch Message ID: 635:8:0 Batch Message ID: 635:9:0 Batch Message ID: 635:10:0 Batch Message ID: 635:11:0``` Now, I "skip" 1 message for that subscription, and now I get 12 ids as expected, but what is totally *unexpected* is that two more of the entries from the prior peek have disappeared (`635:0.0` and `635:0:1`), and now I'm seeing two new message ids `627:132:0` and `627:133:0` : ```Batch Message ID: 627:132:0 Batch Message ID: 627:133:0 Batch Message ID: 635:2:0 Batch Message ID: 635:3:0 Batch Message ID: 635:4:0 Batch Message ID: 635:5:0 Batch Message ID: 635:6:0 Batch Message ID: 635:7:0 Batch Message ID: 635:8:0 Batch Message ID: 635:9:0 Batch Message ID: 635:10:0 Batch Message ID: 635:11:0``` What am I missing here? And which message did I actually skip? ---- 2020-09-14 18:57:51 UTC - Devin G. Bost: My team has always just setup a new consumer to inspect messages because peek has been confusing for us. ---- 2020-09-14 18:59:14 UTC - Devin G. Bost: I can't remember what the three different columns of the message ID mean... I'm trying to remember where that's documented. ---- 2020-09-14 19:00:39 UTC - Raman Gupta: Yeah I can't seem to be able to use `get-message-by-id` with these values -- that command takes a ledger id and an entry id, but the values from peek, assuming ledger is the first entry and entry id is the second, just result in 404s. ---- 2020-09-14 19:01:10 UTC - Raman Gupta: On top of this, my application is seeing messages that aren't even listed in the backlog... `Processing from work queue with msgId=627:135:0:0` . So now I'm even more confused. ---- 2020-09-14 19:04:02 UTC - Raman Gupta: My fundamental issue is my app is not making forward progress: something in the topic is causing an OOM. However, it does process in a couple of threads, so I'm trying to a) figure out which entries in the backlog are the problem, and b) just skip those.
However, when the app restarts, it is reporting processing entirely different messages than are even shown in the backlog according to peek, and skip doesn't tell me which message it actually decided to skip, nor does `skip` allow me to specify particular message ids, I'm having a much harder time at this than I would expect. ---- 2020-09-14 19:09:40 UTC - Raman Gupta: I believe the values in peek are: `<ledgerid>:<entryid>:<partition>` ---- 2020-09-14 19:10:04 UTC - Devin G. Bost: That looks right. ---- 2020-09-14 19:10:43 UTC - Devin G. Bost: Have you tried logging the messages within your application? Also, depending on your message velocity, you can setup a second subscription that does nothing by log the messages somewhere so you can inspect them. ---- 2020-09-14 19:10:52 UTC - Devin G. Bost: Is anyone actually using Pulsar function state in production? ---- 2020-09-14 19:13:37 UTC - Raman Gupta: The application does log a summary, which shows it processing messages that aren't listed in the backlog, which is even more confusing. Re. the second subscription, not a bad idea, but I don't have it now. ---- 2020-09-14 19:14:28 UTC - Devin G. Bost: It seems like your application is nacking messages. ---- 2020-09-14 19:14:53 UTC - Raman Gupta: It is. Does a nack regenerate the message id? That might explain some stuff. ---- 2020-09-14 19:14:59 UTC - Devin G. Bost: That would result in older messages getting put back on the backlog (if they're not getting ack'd) ---- 2020-09-14 19:15:15 UTC - Devin G. Bost: I don't think they need to be explicitly nacked to result in that behavior. ---- 2020-09-14 19:16:09 UTC - Raman Gupta: That makes sense. App picks up message. OOMs. After ack timeout expires, older message shows up in backlog again. ---- 2020-09-14 19:16:14 UTC - Jerry Peng: At Splunk, we haven’t yet but plan to ---- 2020-09-14 19:16:24 UTC - Devin G. Bost: You got it. ---- 2020-09-14 19:16:48 UTC - Devin G. Bost: I don't think the message IDs are getting regenerated because the "new" messages you are seeing have an older ledgerId ---- 2020-09-14 19:17:21 UTC - Raman Gupta: Yes, reappearing after timeout explains the older ids. +1 : Devin G. Bost ---- 2020-09-14 19:17:35 UTC - Devin G. Bost: Do you know if it's currently stable? ---- 2020-09-14 19:19:49 UTC - Jerry Peng: We have made some big fixes in regards to running functions within containers but the core is pretty solid ---- 2020-09-14 19:20:34 UTC - Raman Gupta: That explains what I saw with peek also. `627:129:0` was skipped. `635:0:0` and `635:0:1` were picked up by the app, and messages actively being read by the subscription are probably not shown in the peek any more. Then coincidentally `627:132:0` and `627:133:0` showed up again just to confuse me, but with a good post ipso facto explanation. ---- 2020-09-14 19:54:54 UTC - Raman Gupta: Weird, the redeliveryCount is not being incremented when the message is nacked. What could cause that? I'm positive this used to work. ---- 2020-09-14 20:05:55 UTC - Evan Furman: Are there docs that cover how to handle failure scenarios? We are in the process of playing them out right now but it looks like killing a bookie may have hosed our cluster entirely. ---- 2020-09-14 20:06:08 UTC - Devin G. Bost: Thanks. ---- 2020-09-14 20:06:18 UTC - Evan Furman: we have rackawareness enabled and 4 bookies ---- 2020-09-14 20:06:58 UTC - Devin G. Bost: What version of Pulsar would you say it's stable as-of? ---- 2020-09-14 20:13:48 UTC - Devin G. Bost: I'm not sure about that one. ---- 2020-09-14 20:14:51 UTC - Raman Gupta: Yeah, that theory was not correct. I stopped the app completely, skipped again, and again a similar behavior as what I described originally has occurred. ---- 2020-09-14 20:15:05 UTC - Devin G. Bost: If taking down one bookie took out your cluster, your bookie cluster is too small. ---- 2020-09-14 20:15:14 UTC - Raman Gupta: nack doesn't explain it, the nack timeout is 2 minutes and the app has been stopped for at least 5. ---- 2020-09-14 20:15:49 UTC - Raman Gupta: More weird stuff is happening: I see acked messages whose redelivery counts are not being incremented. ---- 2020-09-14 20:16:05 UTC - Devin G. Bost: @Addison Higham Do you know if there's documentation anywhere about this? I know there are videos about geo-replication, but that's a bit different. ---- 2020-09-14 20:16:20 UTC - Evan Furman: How can we tell if autorecovery is doing it’s thing? ---- 2020-09-14 20:16:40 UTC - Evan Furman: we are running on ec2, not k8s btw ---- 2020-09-14 20:16:53 UTC - Devin G. Bost: It should be expressed in the bookie logs. I don't remember exactly what to look for. ---- 2020-09-14 20:17:28 UTC - Addison Higham: are you running auto-recovery as part of the bookie? or are you running it as a standalone process? ---- 2020-09-14 20:18:44 UTC - Evan Furman: ```############################################################################# ## AutoRecovery settings ############################################################################# # The interval between auditor bookie checks. # The auditor bookie check, checks ledger metadata to see which bookies should # contain entries for each ledger. If a bookie which should contain entries is # unavailable, then the ledger containing that entry is marked for recovery. # Setting this to 0 disabled the periodic check. Bookie checks will still # run when a bookie fails. # The interval is specified in seconds. auditorPeriodicBookieCheckInterval=86400 # The number of entries that a replication will rereplicate in parallel. rereplicationEntryBatchSize=5000 # Auto-replication # The grace period, in seconds, that the replication worker waits before fencing and # replicating a ledger fragment that's still being written to upon bookie failure. # openLedgerRereplicationGracePeriod=30 # Whether the bookie itself can start auto-recovery service also or not autoRecoveryDaemonEnabled=true # How long to wait, in seconds, before starting auto recovery of a lost bookie # lostBookieRecoveryDelay=0``` ---- 2020-09-14 20:20:40 UTC - Evan Furman: i am not sure, this is the from the bookkeeper conf file. ---- 2020-09-14 20:20:47 UTC - Evan Furman: We are using the terraform/ansible deployment ---- 2020-09-14 20:21:05 UTC - Addison Higham: either way, it should be in the autorecovery logs. As far as what should happen, was this the first bookie you killed? or did you kill multiple bookies? If it was your first bookie, then yes, you should look at your persistence policies and ensure that they are set such that you can tolerate the loss of a bookies ---- 2020-09-14 20:21:14 UTC - Evan Furman: <https://github.com/apache/pulsar/blob/f06f0d8baf3975367c3f5a14dc5a0bda692487ba/deployment/terraform-ansible/templates/bookkeeper.conf#L235> ---- 2020-09-14 20:21:22 UTC - Addison Higham: `autoRecoveryDaemonEnabled=true` means it should be running in the bookie ---- 2020-09-14 20:21:40 UTC - Evan Furman: ok, that is what i figured ---- 2020-09-14 20:21:51 UTC - Evan Furman: this was the first bookie I killed ---- 2020-09-14 20:21:59 UTC - Evan Furman: we have 4 — 2 in each AZ ---- 2020-09-14 20:22:18 UTC - Addison Higham: what errors are you seeing? ---- 2020-09-14 20:22:35 UTC - Evan Furman: I saw consumption stop // 0 throughput across the topics in pulsar-manager dashboard ---- 2020-09-14 20:23:45 UTC - Evan Furman: ```bookkeeperClientRegionawarePolicyEnabled=true``` ---- 2020-09-14 20:23:50 UTC - Addison Higham: remind me which version of pulsar you are on? and which client /client version as well ---- 2020-09-14 20:24:09 UTC - Addison Higham: if you look at your broker logs, you should expect to see some errors ---- 2020-09-14 20:24:40 UTC - Raman Gupta: 2.4.1, client is Java, v2.4.1 also ---- 2020-09-14 20:27:35 UTC - Evan Furman: ```18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972561): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] INFO org.apache.bookkeeper.client.LedgerHandle - New Ensemble: [ip-10-3-21-20.ec2.internal:3181, ip-10-3-21-41.ec2.internal:3181, ip-10-3-22-212.ec2.internal:3181] for ledger: 142 18:50:07.662 [bookkeeper-io-12-3] WARN org.apache.bookkeeper.proto.PerChannelBookieClient - Exception caught on:[id: 0x4a2b9097, L:/10.3.22.65:45712 - R:ip-10-3-22-51.ec2.internal/10.3.22.51:3181] cause: readAddress(..) failed: Connection reset by peer 18:50:07.663 [bookkeeper-io-12-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Disconnected from bookie channel [id: 0x4a2b9097, L:/10.3.22.65:45712 ! R:ip-10-3-22-51.ec2.internal/10.3.22.51:3181] 18:50:08.279 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Removing a node: /default-rack/ip-10-3-22-51.ec2.internal:3181 18:50:08.279 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Removing a node: /default-rack/ip-10-3-22-51.ec2.internal:3181 19:13:36.369 [BookKeeperClientScheduler-OrderedScheduler-0-0] WARN org.apache.bookkeeper.client.TopologyAwareEnsemblePlacementPolicy - Failed to resolve network location for ip-10-3-22-51.ec2.internal, using default rack for it : /default-rack. 19:13:36.369 [BookKeeperClientScheduler-OrderedScheduler-0-0] WARN org.apache.bookkeeper.client.TopologyAwareEnsemblePlacementPolicy - Failed to resolve network location for ip-10-3-22-51.ec2.internal, using default rack for it : /default-rack. 19:13:36.369 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Adding a new node: /default-rack/ip-10-3-22-51.ec2.internal:3181 19:13:36.369 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Adding a new node: /default-rack/ip-10-3-22-51.ec2.internal:3181 ^C [root@ip-10-3-22-65 logs]# tail -n30 pulsar-broker.log 18:50:07.661 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972552): Bookie handle is not available 18:50:07.661 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972529): Bookie handle is not available 18:50:07.661 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972540): Bookie handle is not available 18:50:07.661 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972535): Bookie handle is not available 18:50:07.661 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972558): Bookie handle is not available 18:50:07.661 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972532): Bookie handle is not available 18:50:07.661 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972534): Bookie handle is not available 18:50:07.661 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972559): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972526): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972562): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972538): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972522): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972549): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972564): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972546): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972556): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972541): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972525): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972543): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972531): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (142, 972561): Bookie handle is not available 18:50:07.662 [BookKeeperClientWorker-OrderedExecutor-6-0] INFO org.apache.bookkeeper.client.LedgerHandle - New Ensemble: [ip-10-3-21-20.ec2.internal:3181, ip-10-3-21-41.ec2.internal:3181, ip-10-3-22-212.ec2.internal:3181] for ledger: 142 18:50:07.662 [bookkeeper-io-12-3] WARN org.apache.bookkeeper.proto.PerChannelBookieClient - Exception caught on:[id: 0x4a2b9097, L:/10.3.22.65:45712 - R:ip-10-3-22-51.ec2.internal/10.3.22.51:3181] cause: readAddress(..) failed: Connection reset by peer 18:50:07.663 [bookkeeper-io-12-3] INFO org.apache.bookkeeper.proto.PerChannelBookieClient - Disconnected from bookie channel [id: 0x4a2b9097, L:/10.3.22.65:45712 ! R:ip-10-3-22-51.ec2.internal/10.3.22.51:3181] 18:50:08.279 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Removing a node: /default-rack/ip-10-3-22-51.ec2.internal:3181 18:50:08.279 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Removing a node: /default-rack/ip-10-3-22-51.ec2.internal:3181 19:13:36.369 [BookKeeperClientScheduler-OrderedScheduler-0-0] WARN org.apache.bookkeeper.client.TopologyAwareEnsemblePlacementPolicy - Failed to resolve network location for ip-10-3-22-51.ec2.internal, using default rack for it : /default-rack. 19:13:36.369 [BookKeeperClientScheduler-OrderedScheduler-0-0] WARN org.apache.bookkeeper.client.TopologyAwareEnsemblePlacementPolicy - Failed to resolve network location for ip-10-3-22-51.ec2.internal, using default rack for it : /default-rack. 19:13:36.369 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Adding a new node: /default-rack/ip-10-3-22-51.ec2.internal:3181 19:13:36.369 [BookKeeperClientScheduler-OrderedScheduler-0-0] INFO org.apache.bookkeeper.net.NetworkTopologyImpl - Adding a new node: /default-rack/ip-10-3-22-51.ec2.internal:3181``` ---- 2020-09-14 20:41:29 UTC - Devin G. Bost: Is your Zookeeper cluster healthy? ---- 2020-09-14 20:42:28 UTC - Evan Furman: Looks to be ---- 2020-09-14 20:42:30 UTC - Devin G. Bost: Also, I'm guessing that `ip-10-3-22-51.ec2.internal` is the node you took down. Is that right? ---- 2020-09-14 20:42:51 UTC - Evan Furman: yep ---- 2020-09-14 20:43:05 UTC - Evan Furman: ```[root@ip-10-3-22-51 logs]# grep -i auto pulsar-bookie.log "autoRecoveryDaemonEnabled" : "true", 15:30:17.327 [main] INFO org.apache.bookkeeper.server.Main - Load lifecycle component : org.apache.bookkeeper.server.service.AutoRecoveryService 18:50:07.390 [component-shutdown-thread] INFO org.apache.bookkeeper.replication.AutoRecoveryMain - Shutting down auto recovery: 0 18:50:07.390 [component-shutdown-thread] INFO org.apache.bookkeeper.replication.AutoRecoveryMain - Shutting down AutoRecovery 18:50:07.962 [AutoRecoveryDeathWatcher-3181] INFO org.apache.bookkeeper.replication.AutoRecoveryMain - AutoRecoveryDeathWatcher noticed the AutoRecovery is not running any more,exiting the watch loop! 18:50:07.963 [AutoRecoveryDeathWatcher-3181] ERROR org.apache.bookkeeper.common.component.ComponentStarter - Triggered exceptionHandler of Component: bookie-server because of Exception in Thread: Thread[AutoRecoveryDeathWatcher-3181,5,main] java.lang.RuntimeException: AutoRecovery is not running any more at org.apache.bookkeeper.replication.AutoRecoveryMain$AutoRecoveryDeathWatcher.run(AutoRecoveryMain.java:237) ~[org.apache.bookkeeper-bookkeeper-server-4.10.0.jar:4.10.0] "autoRecoveryDaemonEnabled" : "true", 19:13:35.965 [main] INFO org.apache.bookkeeper.server.Main - Load lifecycle component : org.apache.bookkeeper.server.service.AutoRecoveryService 20:15:56.608 [main] INFO org.apache.bookkeeper.replication.AutoRecoveryMain - Load lifecycle component : org.apache.bookkeeper.server.service.AutoRecoveryService 20:15:56.615 [main] INFO org.apache.bookkeeper.common.component.ComponentStarter - Starting component autorecovery-server. at org.apache.bookkeeper.replication.AutoRecoveryMain.doMain(AutoRecoveryMain.java:334) [org.apache.bookkeeper-bookkeeper-server-4.10.0.jar:4.10.0] at org.apache.bookkeeper.replication.AutoRecoveryMain.main(AutoRecoveryMain.java:308) [org.apache.bookkeeper-bookkeeper-server-4.10.0.jar:4.10.0] 20:15:56.938 [main] ERROR org.apache.bookkeeper.common.component.ComponentStarter - Triggered exceptionHandler of Component: autorecovery-server because of Exception in Thread: Thread[main,5,main] at org.apache.bookkeeper.replication.AutoRecoveryMain.doMain(AutoRecoveryMain.java:334) [org.apache.bookkeeper-bookkeeper-server-4.10.0.jar:4.10.0] at org.apache.bookkeeper.replication.AutoRecoveryMain.main(AutoRecoveryMain.java:308) [org.apache.bookkeeper-bookkeeper-server-4.10.0.jar:4.10.0] 20:15:56.940 [component-shutdown-thread] INFO org.apache.bookkeeper.common.component.ComponentStarter - Closing component autorecovery-server in shutdown hook. 20:15:56.942 [component-shutdown-thread] INFO org.apache.bookkeeper.replication.AutoRecoveryMain - Shutting down auto recovery: 0 20:15:56.942 [component-shutdown-thread] INFO org.apache.bookkeeper.replication.AutoRecoveryMain - Shutting down AutoRecovery 20:15:57.199 [component-shutdown-thread] INFO org.apache.bookkeeper.common.component.ComponentStarter - Closed component autorecovery-server in shutdown hook successfully. Exiting. 20:15:57.984 [AutoRecoveryDeathWatcher-3181] INFO org.apache.bookkeeper.replication.AutoRecoveryMain - AutoRecoveryDeathWatcher noticed the AutoRecovery is not running any more,exiting the watch loop! 20:15:57.984 [AutoRecoveryDeathWatcher-3181] ERROR org.apache.bookkeeper.common.component.ComponentStarter - Triggered exceptionHandler of Component: autorecovery-server because of Exception in Thread: Thread[AutoRecoveryDeathWatcher-3181,5,main] java.lang.RuntimeException: AutoRecovery is not running any more``` ---- 2020-09-14 20:43:18 UTC - Evan Furman: just stopped the bookie service ---- 2020-09-14 20:44:32 UTC - Devin G. Bost: Yeah, it looks like autorecovery failed for some reason. ---- 2020-09-14 20:45:26 UTC - Devin G. Bost: Are you able to bring that bookie back up? ---- 2020-09-14 20:45:32 UTC - Devin G. Bost: What was the reason for taking it down? ---- 2020-09-14 20:45:49 UTC - Evan Furman: ```18:50:07.593 [bookie-io-1-3] INFO org.apache.bookkeeper.proto.BookieRequestHandler - Channels disconnected: [id: 0x2e5a72e2, L:/10.3.22.51:3181 ! R:/10.3.22.65:45594] 18:50:07.593 [bookie-io-1-3] INFO org.apache.bookkeeper.proto.BookieRequestHandler - Channels disconnected: [id: 0xd90787af, L:/10.3.22.51:3181 ! R:/10.3.21.142:53514] 18:50:07.593 [bookie-io-1-3] INFO org.apache.bookkeeper.proto.BookieRequestHandler - Channels disconnected: [id: 0x3cfa3b85, L:/10.3.22.51:3181 ! R:/10.3.22.80:54204] 18:50:07.639 [bookie-io-1-2] INFO org.apache.bookkeeper.proto.AuthHandler - Authentication success on server side 18:50:07.648 [bookie-io-1-1] INFO org.apache.bookkeeper.proto.AuthHandler - Authentication success on server side 18:50:07.668 [component-shutdown-thread] INFO org.apache.bookkeeper.bookie.Bookie - Shutting down Bookie-3181 with exitCode 0 18:50:07.668 [component-shutdown-thread] INFO org.apache.bookkeeper.bookie.Bookie - Turning bookie to read only during shut down 18:50:07.668 [component-shutdown-thread] INFO org.apache.bookkeeper.bookie.SyncThread - Shutting down SyncThread 18:50:07.962 [AutoRecoveryDeathWatcher-3181] INFO org.apache.bookkeeper.replication.AutoRecoveryMain - AutoRecoveryDeathWatcher noticed the AutoRecovery is not running any m ore,exiting the watch loop! 18:50:07.963 [AutoRecoveryDeathWatcher-3181] ERROR org.apache.bookkeeper.common.component.ComponentStarter - Triggered exceptionHandler of Component: bookie-server because of Exception in Thread: Thread[AutoRecoveryDeathWatcher-3181,5,main] java.lang.RuntimeException: AutoRecovery is not running any more at org.apache.bookkeeper.replication.AutoRecoveryMain$AutoRecoveryDeathWatcher.run(AutoRecoveryMain.java:237) ~[org.apache.bookkeeper-bookkeeper-server-4.10.0.jar:4.1 0.0] 18:50:08.224 [SyncThread-7-1] INFO org.apache.bookkeeper.bookie.SyncThread - Flush ledger storage at checkpoint CheckpointList{checkpoints=[LogMark: logFileId - 160009741778 5 , logFileOffset - 1839800320]}. 18:50:08.225 [component-shutdown-thread] INFO org.apache.bookkeeper.bookie.Journal - Shutting down Journal 18:50:08.225 [ForceWriteThread] INFO org.apache.bookkeeper.bookie.Journal - ForceWrite thread interrupted 18:50:08.226 [BookieJournal-3181] INFO org.apache.bookkeeper.bookie.Journal - Journal exits when shutting down 18:50:08.226 [BookieJournal-3181] INFO org.apache.bookkeeper.bookie.Journal - Journal exited loop! 18:50:08.228 [component-shutdown-thread] INFO org.apache.bookkeeper.bookie.Journal - Finished Shutting down Journal thread 18:50:08.228 [Bookie-3181] INFO org.apache.bookkeeper.bookie.Bookie - Journal thread(s) quit. 18:50:08.231 [component-shutdown-thread] INFO org.apache.bookkeeper.bookie.GarbageCollectorThread - Shutting down GarbageCollectorThread 18:50:08.231 [component-shutdown-thread] INFO org.apache.bookkeeper.bookie.EntryLogger - Stopping EntryLogger 18:50:08.237 [component-shutdown-thread] INFO org.apache.bookkeeper.bookie.EntryLoggerAllocator - Stopped entry logger preallocator. 18:50:08.274 [component-shutdown-thread] INFO org.apache.bookkeeper.bookie.LedgerDirsMonitor - Shutting down LedgerDirsMonitor 18:50:08.379 [main-EventThread] INFO org.apache.zookeeper.ClientCnxn - EventThread shut down for session: 0xd700001a86b10001 18:50:08.379 [component-shutdown-thread] INFO org.apache.zookeeper.ZooKeeper - Session: 0xd700001a86b10001 closed 18:50:08.408 [component-shutdown-thread] INFO org.apache.bookkeeper.common.component.ComponentStarter - Closed component bookie-server in shutdown hook successfully. Exiting . 19:13:33.392 [main] INFO org.apache.bookkeeper.server.Main - Using configuration file /opt/pulsar/conf/bookkeeper.conf``` ---- 2020-09-14 20:46:03 UTC - Evan Furman: We are testing failure scenarios ---- 2020-09-14 20:46:09 UTC - Evan Furman: this is not yet a production cluster ---- 2020-09-14 20:48:36 UTC - Devin G. Bost: Ah, gotcha. ---- 2020-09-14 20:48:42 UTC - Evan Furman: I’m grasping here but maybe because it’s running as part of the bookie, when i shut down the service, it shutdown the autorecovery too? ---- 2020-09-14 20:49:20 UTC - Evan Furman: Maybe running it as a separate service is the way to go? ---- 2020-09-14 20:50:19 UTC - Devin G. Bost: Ah, that might explain it. The exception says it right there `AutoRecovery is not running any more` ---- 2020-09-14 20:50:51 UTC - Devin G. Bost: We currently run our clusters with docker on baremetal, and we've talked about moving to k8s. ---- 2020-09-14 20:51:02 UTC - Devin G. Bost: I think most people are running Pulsar on k8s. ---- 2020-09-14 20:51:17 UTC - Evan Furman: We started with K8s but had all kinds of issues so we ended up on bare metal :smile: ---- 2020-09-14 20:51:40 UTC - Devin G. Bost: Yeah, docker on bare metal has worked pretty well for us. We avoided k8s at the beginning for that same reason. ---- 2020-09-14 20:52:13 UTC - Devin G. Bost: Are you guys currently operating Pulsar in prod or just testing it out? ---- 2020-09-14 20:52:15 UTC - Evan Furman: I’m trying to think of a scenario when you would want to run autorecovery as part of bookie process. It seems like a death wish… ---- 2020-09-14 20:52:37 UTC - Evan Furman: We are tweaking/testing our terraform/ansible in order to build a production cluster ---- 2020-09-14 20:52:47 UTC - Devin G. Bost: Cool ---- 2020-09-14 20:53:07 UTC - Evan Furman: We’re hoping to replace SQS entirely ---- 2020-09-14 20:53:37 UTC - Devin G. Bost: Cool. I don't know enough about Bookie autorecovery to provide more guidance there. @Sijie Guo would probably know. +1 : Evan Furman ---- 2020-09-14 20:56:52 UTC - Raman Gupta: I don't think there is any *fundamental* reason why recovery can't be run as part of the bookie. The recovery daemon does not itself maintain any state -- it simply watches for a downed bookie and kicks off processing to replicate the ledgers on that bookie to other bookies. If all your bookies are running it, then losing a bookie along with its recovery daemon should be no big deal. ---- 2020-09-14 20:58:49 UTC - Raman Gupta: IIUC you don't need any autorecovery daemons at all to have a working cluster. ---- 2020-09-14 21:05:51 UTC - Addison Higham: catching up here...as mentioned, @Evan Furman you can have multiple instances of auto-recovery, so it shouldn't be a problem if it dies on one. What should happen in your broker when a bookie dies is dependent upon your settings. For example, if you have 4 bookies and a persistence policy 3/3/3, then upon being unable to write, it will close that ledger, create a new ensembles, and continue writing. At that point, if you never bring back the nodes, then autorecovery will come in and re-replicate the ledgers such that the ledgers exists on 3 nodes again, but it does not need to be running for new writes to work ---- 2020-09-14 21:08:09 UTC - Addison Higham: so, if you can't write after losing a single bookie, then it is likely either: 1. something your settings is such that the timeout for a down bookie is taking too long. 2. your persistence settings require 4 bookies to write to, and since you only have 3, it fails ---- 2020-09-14 21:09:36 UTC - Addison Higham: @Evan Furman and looking closer at the logs: ``` New Ensemble: [ip-10-3-21-20.ec2.internal:3181, ip-10-3-21-41.ec2.internal:3181, ip-10-3-22-212.ec2.internal:3181] for ledger: 142``` That looks to be the expected message, and afterwards, we would expect writes to continue again, did it recover? ---- 2020-09-14 21:12:01 UTC - Evan Furman: the writes did but the reads did not ---- 2020-09-14 21:12:13 UTC - Evan Furman: the out throughput is still 0 ---- 2020-09-14 21:13:37 UTC - Evan Furman: ```# Number of bookies to use when creating a ledger managedLedgerDefaultEnsembleSize=3 # Number of copies to store for each message managedLedgerDefaultWriteQuorum=2 # Number of guaranteed copies (acks to wait before write is complete) managedLedgerDefaultAckQuorum=2``` ---- 2020-09-14 21:19:31 UTC - Evan Furman: ```# Interval to watch whether bookie is dead or not, in milliseconds bookieDeathWatchInterval=1000``` ---- 2020-09-14 21:21:07 UTC - Raman Gupta: Those are default values, is the namespace configured with the same ensemble/writeq/ackq? ---- 2020-09-14 21:21:17 UTC - Addison Higham: those are the defaults, but you can overwrite it per each namespace. if you run `pulsar-admin namespaces policies <namespace>` what is the persistence policy for the namespace you are using? ---- 2020-09-14 21:23:40 UTC - Evan Furman: ```[root@ip-10-3-22-65 bin]# ./pulsar-admin namespaces policies public/default { "auth_policies" : { "namespace_auth" : { }, "destination_auth" : { }, "subscription_auth_roles" : { } }, "replication_clusters" : [ "pulsar-cluster-evan" ], "bundles" : { "boundaries" : [ "0x00000000", "0x10000000", "0x20000000", "0x30000000", "0x40000000", "0x50000000", "0x60000000", "0x70000000", "0x80000000", "0x90000000", "0xa0000000", "0xb0000000", "0xc0000000", "0xd0000000", "0xe0000000", "0xf0000000", "0xffffffff" ], "numBundles" : 16 }, "backlog_quota_map" : { "destination_storage" : { "limit" : 107374182400, "policy" : "producer_request_hold" } }, "clusterDispatchRate" : { }, "topicDispatchRate" : { "pulsar-cluster-evan" : { "dispatchThrottlingRateInMsg" : 0, "dispatchThrottlingRateInByte" : 0, "relativeToPublishRate" : false, "ratePeriodInSecond" : 1 } }, "subscriptionDispatchRate" : { "pulsar-cluster-evan" : { "dispatchThrottlingRateInMsg" : 0, "dispatchThrottlingRateInByte" : 0, "relativeToPublishRate" : false, "ratePeriodInSecond" : 1 } }, "replicatorDispatchRate" : { }, "clusterSubscribeRate" : { "pulsar-cluster-evan" : { "subscribeThrottlingRatePerConsumer" : 0, "ratePeriodInSecond" : 30 } }, "publishMaxMessageRate" : { }, "latency_stats_sample_rate" : { }, "message_ttl_in_seconds" : 0, "subscription_expiration_time_minutes" : 0, "deleted" : false, "encryption_required" : false, "subscription_auth_mode" : "None", "max_producers_per_topic" : 0, "max_consumers_per_topic" : 0, "max_consumers_per_subscription" : 0, "max_unacked_messages_per_consumer" : 50000, "max_unacked_messages_per_subscription" : 200000, "compaction_threshold" : 0, "offload_threshold" : -1, "schema_auto_update_compatibility_strategy" : "Full", "schema_compatibility_strategy" : "UNDEFINED", "is_allow_auto_update_schema" : true, "schema_validation_enforced" : false }``` ---- 2020-09-14 21:23:46 UTC - Evan Furman: we are using the default ns ---- 2020-09-14 21:25:39 UTC - Addison Higham: hrm that all looks correct, is this single topic or a partitioned topic? also, what version of pulsar are you using? ---- 2020-09-14 21:26:25 UTC - Evan Furman: `2.6.1` and we are using partitioned ---- 2020-09-14 21:32:12 UTC - Evan Furman: ---- 2020-09-14 21:32:22 UTC - Evan Furman: This is the state we are in now ---- 2020-09-14 21:32:32 UTC - Evan Furman: backlogging ---- 2020-09-14 22:05:45 UTC - Addison Higham: hrm... this seems strange, can you grab a snapshot of your logs for your different brokers for the first 5 minutes after you killed the bookie? One thing you can try since you are using partitioned topics: unload a single partition using `pulsar-admin topics unload <full topic name including partition number>`. If that fixes it, then it means something has gone awry in having the readers recover ---- 2020-09-15 00:49:31 UTC - Addison Higham: did you find anything here? if there is any questions I can help answer please let me know ---- 2020-09-15 02:22:03 UTC - Sankararao Routhu: Hi @Penghui Li thanks for the reply, I have two consumers with stickyHashRange, I am sending two different types of messages( few messages with key1 and other messages with key2). Consumer1 has sticky hash range for key1 and consumer2 has sticky hash range for key2. Consumer1 and consumer2 are receiving messages based on the key. But if one the consumers are down say consumer2 is down then consumer1 is getting both key1 and key2 messages. Is this expected? ---- 2020-09-15 02:30:24 UTC - Penghui Li: No, it is a unexpected behavior ---- 2020-09-15 02:30:34 UTC - Penghui Li: Which version are you using? ---- 2020-09-15 02:50:30 UTC - Sankararao Routhu: 2.6.0 @Penghui Li ---- 2020-09-15 03:35:08 UTC - Sankararao Routhu: is it a bug in 2.6.0 @Penghui Li? ---- 2020-09-15 04:04:26 UTC - Penghui Li: I’m not sure, could you please help create a github issue, so that we can track this problem well. ---- 2020-09-15 06:24:12 UTC - Maulin Vasavada: @Maulin Vasavada has joined the channel ---- 2020-09-15 07:42:59 UTC - Enrico: Hi experts, i'm new to pulsar, and i have a question, there is KeySharedPolicy in c++? Because we need to send 10Gbit/s and from producer we haven't problem but our problem is on consumer side, because wi can't use shared mode because we need ordinate messagges and a possibility is keyshared ad i would test keysharedpolicy to control the flow. Sorry if it seems like a trivial question but I have been working on it for a week and I do not jump out HIHIHI ---- 2020-09-15 08:08:34 UTC - Rattanjot Singh: I have two clusters . Cluster A and Cluster B. Input topic is Cluster A and output topic is in Cluster B. Is it possible to specify the cluster url for the output topic in pulsar function. ----
