devinbost commented on issue #6054:
URL: https://github.com/apache/pulsar/issues/6054#issuecomment-840221892
After adding a lot of debug log lines, this is what **healthy traffic**
should look like for the ack flow (starting from when the producer triggers the
SEND command to when the SEND_RECEIPT command is sent):
```
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG org.apache.pulsar.broker.service.ServerCnx - Calling
ServerCnx.handleSend(..)
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG org.apache.pulsar.broker.service.ServerCnx -
[/10.20.69.37:50086] Received send message request. producer: 0:242435
example-cluster-235-0:242435 size: 37566, partition key is: null, ordering key
is null
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG org.apache.pulsar.broker.service.ServerCnx - Called
startSendOperation(..) in ServerCnx.handleSend(..) for producer
Producer{topic=PersistentTopic{topic=persistent://myTenant/myNamespace/bot-filtered},
client=/10.20.69.37:50086, producerName=example-cluster-235-0, producerId=0}
with messages 12
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG org.apache.pulsar.broker.service.ServerCnx -
send.hasHighestSequenceId() (true) && send.getSequenceId() (242435) <=
send.getHighestSequenceId() (242446)
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG org.apache.pulsar.broker.service.Producer - Calling
Producer.publishMessageToTopic([headersAndPayload], 242435, 242446, 12, false
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG
org.apache.pulsar.broker.service.persistent.PersistentTopic - Calling
PersistentTopic.publishMessage([headersAndPayload], publishContext) for
publishContext:
Producer.MessagePublishContext(producer=Producer{topic=PersistentTopic{topic=persistent://myTenant/myNamespace/bot-filtered},
client=/10.20.69.37:50086, producerName=example-cluster-235-0, producerId=0},
sequenceId=242435, ledgerId=-1, entryId=-1,
rateIn=org.apache.pulsar.common.stats.Rate@1bcfab4e, msgSize=37566,
batchSize=12, chunked=false, startTimeNs=15631623317576155,
originalProducerName=null, originalSequenceId=-1, highestSequenceId=242446,
originalHighestSequenceId=-1,
recyclerHandle=io.netty.util.Recycler$DefaultHandle@5afb09fa)
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG
org.apache.pulsar.broker.service.persistent.PersistentTopic - pendingWriteOps
is: 1
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG
org.apache.pulsar.broker.service.persistent.PersistentTopic - isFenced is: false
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG
org.apache.pulsar.broker.service.persistent.PersistentTopic -
PersistentTopic.publishMessage(..) status is NotDup. PublishContext is
Producer.MessagePublishContext(producer=Producer{topic=PersistentTopic{topic=persistent://myTenant/myNamespace/bot-filtered},
client=/10.20.69.37:50086, producerName=example-cluster-235-0, producerId=0},
sequenceId=242435, ledgerId=-1, entryId=-1,
rateIn=org.apache.pulsar.common.stats.Rate@1bcfab4e, msgSize=37566,
batchSize=12, chunked=false, startTimeNs=15631623317576155,
originalProducerName=null, originalSequenceId=-1, highestSequenceId=242446,
originalHighestSequenceId=-1,
recyclerHandle=io.netty.util.Recycler$DefaultHandle@5afb09fa)
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG
org.apache.pulsar.broker.service.persistent.PersistentTopic - Calling
PersistentTopic.asyncAddEntry(..) for PublishContext
Producer.MessagePublishContext(producer=Producer{topic=PersistentTopic{topic=persistent://myTenant/myNamespace/bot-filtered},
client=/10.20.69.37:50086, producerName=example-cluster-235-0, producerId=0},
sequenceId=242435, ledgerId=-1, entryId=-1,
rateIn=org.apache.pulsar.common.stats.Rate@1bcfab4e, msgSize=37566,
batchSize=12, chunked=false, startTimeNs=15631623317576155,
originalProducerName=null, originalSequenceId=-1, highestSequenceId=242446,
originalHighestSequenceId=-1,
recyclerHandle=io.netty.util.Recycler$DefaultHandle@5afb09fa)
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] asyncAddEntry size=37566
state=LedgerOpened
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG org.apache.bookkeeper.mledger.impl.OpAddEntry - Running
OpAddEntry.createOpAddEntry(..)
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG org.apache.bookkeeper.mledger.impl.OpAddEntry - In
OpAddEntry.createOpAddEntry, OpAddEntry is
myTenant/myNamespace/persistent/bot-filtered
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG org.apache.bookkeeper.mledger.impl.OpAddEntry - Created
new OpAddEntry myTenant/myNamespace/persistent/bot-filtered
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,177
[pulsar-io-28-60] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
About to schedule internalAsyncAddEntry(..) on
myTenant/myNamespace/persistent/bot-filtered in
ManagedLedgerImpl.asyncAddEntry(..)
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,178
[bookkeeper-ml-workers-OrderedExecutor-5-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Calling
ManagedLedgerImpl.internalAsyncAddEntry(..) for OpAddEntry
myTenant/myNamespace/persistent/bot-filtered
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,178
[bookkeeper-ml-workers-OrderedExecutor-5-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - pendingAddEntries is
size 1
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,178
[bookkeeper-ml-workers-OrderedExecutor-5-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - State is LedgerOpened
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,178
[bookkeeper-ml-workers-OrderedExecutor-5-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Calling else in
ManagedLedgerImpl.internalAsyncAddEntry(..) for state LedgerOpened
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,178
[bookkeeper-ml-workers-OrderedExecutor-5-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] Write into current ledger
lh=3219013 entries=7
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,178
[bookkeeper-ml-workers-OrderedExecutor-5-0] DEBUG
org.apache.bookkeeper.mledger.impl.OpAddEntry - Calling OpAddEntry.initiate()
for OpAddEntry myTenant/myNamespace/persistent/bot-filtered
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,179
[BookKeeperClientWorker-OrderedExecutor-37-0] DEBUG
org.apache.bookkeeper.mledger.impl.OpAddEntry -
[myTenant/myNamespace/persistent/bot-filtered]
[myTenant/myNamespace/persistent/bot-filtered] write-complete:
ledger-id=3219013 entry-id=6 size=37566 rc=0
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,180
[bookkeeper-ml-workers-OrderedExecutor-5-0] DEBUG
org.apache.bookkeeper.mledger.impl.OpAddEntry - Calling OpAddEntry.safeRun().
firstInQueue OpAddEntry is myTenant/myNamespace/persistent/bot-filtered
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,180
[bookkeeper-ml-workers-OrderedExecutor-5-0] DEBUG
org.apache.bookkeeper.mledger.impl.OpAddEntry - Calling else where cb != null
in OpAddEntry.safeRun()
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,180
[bookkeeper-ml-workers-OrderedExecutor-5-0] DEBUG
org.apache.pulsar.broker.service.persistent.PersistentTopic - Calling
PersistentTopic.addComplete(..) with PublishContext
Producer.MessagePublishContext(producer=Producer{topic=PersistentTopic{topic=persistent://myTenant/myNamespace/bot-filtered},
client=/10.20.69.37:50086, producerName=example-cluster-235-0, producerId=0},
sequenceId=242435, ledgerId=-1, entryId=-1,
rateIn=org.apache.pulsar.common.stats.Rate@1bcfab4e, msgSize=37566,
batchSize=12, chunked=false, startTimeNs=15631623317576155,
originalProducerName=null, originalSequenceId=-1, highestSequenceId=242446,
originalHighestSequenceId=-1,
recyclerHandle=io.netty.util.Recycler$DefaultHandle@5afb09fa)
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,180
[bookkeeper-ml-workers-OrderedExecutor-5-0] DEBUG
org.apache.pulsar.broker.service.Producer - Calling
Producer.MessagePublishContext.completed([exception], 3219013, 6)
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,180
[bookkeeper-ml-workers-OrderedExecutor-5-0] DEBUG
org.apache.pulsar.broker.service.Producer -
[PersistentTopic{topic=persistent://myTenant/myNamespace/bot-filtered}]
[example-cluster-235-0] [0] triggered send callback. cnx /10.20.69.37:50086,
sequenceId 242435
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,180
[pulsar-io-28-60] DEBUG org.apache.pulsar.broker.service.Producer - Calling
Producer.MessagePublishContext.run()
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,180
[pulsar-io-28-60] DEBUG org.apache.pulsar.broker.service.Producer -
[PersistentTopic{topic=persistent://myTenant/myNamespace/bot-filtered}]
[example-cluster-235-0] [0] Persisted message. cnx
org.apache.pulsar.broker.service.ServerCnx@4f9ad6cb, sequenceId 242435
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,180
[pulsar-io-28-60] DEBUG org.apache.pulsar.broker.service.Producer - About to
call producer.cnx.getCommandSender().sendSendReceiptResponse(..)
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,180
[pulsar-io-28-60] DEBUG
org.apache.pulsar.broker.service.PulsarCommandSenderImpl - Calling
PulsarCommandSenderImpl.sendSendReceiptResponse(0,242435,242446,3219013,6)
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,180
[pulsar-io-28-60] DEBUG org.apache.pulsar.broker.service.ServerCnx - Calling
ServerCnx.completedSendOperation(false,37566)
May 12 13:54:31 fab08 822c6b930733: 2021-05-12T19:54:31,180
[pulsar-io-28-60] DEBUG org.apache.pulsar.broker.service.ServerCnx -
pendingSendRequest 1 and resumeReadsThreshold 500
```
In the unhealthy case, we don't see that at all. I'm not even seeing
activity on that thread. The only activity in the logs that I'm seeing on that
broker is this:
```
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,608
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] Ledger already created when
timeout task is triggered
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,608
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] createComplete rc=-23 ledger=-1
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,608
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
checkAndCompleteLedgerOpTask(int rc, LedgerHandle lh, Object ctx) is true
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,608
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Calling
checkAndCompleteLedgerOpTask(rc, lh, ctx)) on
ManagedLedgerImpl.createComplete(..)
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,659
[bookkeeper-ml-scheduler-OrderedScheduler-0-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] Ledger already created when
timeout task is triggered
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,659
[bookkeeper-ml-scheduler-OrderedScheduler-0-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] createComplete rc=-23 ledger=-1
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,659
[bookkeeper-ml-scheduler-OrderedScheduler-0-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
checkAndCompleteLedgerOpTask(int rc, LedgerHandle lh, Object ctx) is true
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,659
[bookkeeper-ml-scheduler-OrderedScheduler-0-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Calling
checkAndCompleteLedgerOpTask(rc, lh, ctx)) on
ManagedLedgerImpl.createComplete(..)
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,711
[bookkeeper-ml-scheduler-OrderedScheduler-5-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] Ledger already created when
timeout task is triggered
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,711
[bookkeeper-ml-scheduler-OrderedScheduler-5-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] createComplete rc=-23 ledger=-1
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,711
[bookkeeper-ml-scheduler-OrderedScheduler-5-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
checkAndCompleteLedgerOpTask(int rc, LedgerHandle lh, Object ctx) is true
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,711
[bookkeeper-ml-scheduler-OrderedScheduler-5-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Calling
checkAndCompleteLedgerOpTask(rc, lh, ctx)) on
ManagedLedgerImpl.createComplete(..)
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,745
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] Ledger already created when
timeout task is triggered
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,745
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] createComplete rc=-23 ledger=-1
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,745
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
checkAndCompleteLedgerOpTask(int rc, LedgerHandle lh, Object ctx) is true
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,745
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Calling
checkAndCompleteLedgerOpTask(rc, lh, ctx)) on
ManagedLedgerImpl.createComplete(..)
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,777
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] Ledger already created when
timeout task is triggered
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,777
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] createComplete rc=-23 ledger=-1
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,777
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
checkAndCompleteLedgerOpTask(int rc, LedgerHandle lh, Object ctx) is true
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,777
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Calling
checkAndCompleteLedgerOpTask(rc, lh, ctx)) on
ManagedLedgerImpl.createComplete(..)
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,810
[bookkeeper-ml-scheduler-OrderedScheduler-1-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] Ledger already created when
timeout task is triggered
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,810
[bookkeeper-ml-scheduler-OrderedScheduler-1-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] createComplete rc=-23 ledger=-1
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,810
[bookkeeper-ml-scheduler-OrderedScheduler-1-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
checkAndCompleteLedgerOpTask(int rc, LedgerHandle lh, Object ctx) is true
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,810
[bookkeeper-ml-scheduler-OrderedScheduler-1-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Calling
checkAndCompleteLedgerOpTask(rc, lh, ctx)) on
ManagedLedgerImpl.createComplete(..)
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,847
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] Ledger already created when
timeout task is triggered
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,847
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[myTenant/myNamespace/persistent/bot-filtered] createComplete rc=-23 ledger=-1
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,847
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
checkAndCompleteLedgerOpTask(int rc, LedgerHandle lh, Object ctx) is true
May 12 14:20:51 fab08 822c6b930733: 2021-05-12T20:20:51,847
[bookkeeper-ml-scheduler-OrderedScheduler-7-0] DEBUG
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - Calling
checkAndCompleteLedgerOpTask(rc, lh, ctx)) on
ManagedLedgerImpl.createComplete(..)
[followed by ping/ping activity]
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
[email protected]
