fracasula commented on issue #7682:
URL: https://github.com/apache/pulsar/issues/7682#issuecomment-694085248
Hi guys, about the Golang deadlock, I'm able to replicate it with the latest
image too (i.e. `streamnative/pulsar-all:2.6.1-sn-3`). It still shows that the
client is stucks acking but it may not just be a client issue like suggested by
@alexku7. By further developing my test I was able to overlap the logs of
client and server and I can say that I consistenly get this on the server side
each time the client gets stuck:
```
time="2020-09-17T09:15:46+02:00" level=info msg="Error reading from
connection" error="Short read when reading frame size: read tcp
[::1]:48104->[::1]:32771: use of closed network connection"
local_addr="[::1]:48104" remote_addr="pulsar://localhost:32771"
07:15:46.482 [pulsar-io-51-16] INFO
org.apache.pulsar.broker.service.ServerCnx - Closed connection from
/172.17.0.1:38668
07:15:46.482 [pulsar-io-51-16] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers
- Removed consumer
Consumer{subscription=PersistentSubscription{topic=persistent://public/default/topic-name-61b9697b6f087aca,
name=subscription-name-756c1ab9019bbcdc}, consumerId=1,
consumerName=consumer-name-249de6d4895d0e15, address=/172.17.0.1:38668} with
pending 200 acks
07:15:46.486 [bookkeeper-ml-workers-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl -
[public/default/persistent/topic-name-61b9697b6f087aca-subscription-name-756c1ab9019bbcdc]
Rewind from 13:700 to 13:400
consumer_partition_integration_test.go:112: [2020-09-17
09:15:46.62477658 +0200 CEST m=+181.898034767] Trying to ack 13:426:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446798277 +0200 CEST m=+171.004720824] Trying to ack 13:1318:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.44681232 +0200 CEST m=+171.004734868] Trying to ack 13:1332:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.44682636 +0200 CEST m=+171.004748901] Trying to ack 13:1334:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446840804 +0200 CEST m=+171.004763351] Trying to ack 13:1337:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446756504 +0200 CEST m=+171.004679062] Trying to ack 13:1324:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446845301 +0200 CEST m=+171.004767844] Trying to ack 13:1338:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446863899 +0200 CEST m=+171.004786443] Trying to ack 13:1340:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446876519 +0200 CEST m=+171.004799061] Trying to ack 13:1341:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446783149 +0200 CEST m=+171.004705702] Trying to ack 13:1328:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446772341 +0200 CEST m=+171.004694903] Trying to ack 13:1322:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446789742 +0200 CEST m=+171.004712290] Trying to ack 13:1321:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446902955 +0200 CEST m=+171.004825503] Trying to ack 13:1345:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.44692216 +0200 CEST m=+171.004844705] Trying to ack 13:1347:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446938844 +0200 CEST m=+171.004861396] Trying to ack 13:1348:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446957473 +0200 CEST m=+171.004880021] Trying to ack 13:1351:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446980957 +0200 CEST m=+171.004903502] Trying to ack 13:1349:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446985213 +0200 CEST m=+171.004907763] Trying to ack 13:1353:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446798504 +0200 CEST m=+171.004721046] Trying to ack 13:1323:0
consumer_partition_integration_test.go:112: [2020-09-16
18:16:12.446791901 +0200 CEST m=+171.004714458] Trying to ack 13:1326:0
...
```
Do you think that's something that could cause the consumer to hang forever
waiting for those pending acks to be processed?
I ran it multiple times, here's the output the second time:
```
08:33:20.866 [pulsar-io-51-7] INFO
org.apache.pulsar.broker.service.ServerCnx - [/172.17.0.1:40022] Created
subscription on topic persistent://public/default/topic-name-61b9697b6f087aca /
subscription-name-2da7ed37505244dc
08:33:20.960 [pulsar-io-51-7] INFO
org.apache.pulsar.broker.service.ServerCnx - Closed connection from
/172.17.0.1:40022
08:33:20.960 [pulsar-io-51-7] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers
- Removed consumer
Consumer{subscription=PersistentSubscription{topic=persistent://public/default/topic-name-61b9697b6f087aca,
name=subscription-name-2da7ed37505244dc}, consumerId=1,
consumerName=consumer-name-748c24a16b99354a, address=/172.17.0.1:40022} with
pending 148 ack
```
Third:
```
08:34:45.073 [pulsar-io-51-8] INFO
org.apache.pulsar.broker.service.ServerCnx - New connection from
/172.17.0.1:40030
08:34:45.074 [pulsar-io-51-8] INFO
org.apache.pulsar.broker.service.ServerCnx - [/172.17.0.1:40030] Subscribing on
topic persistent://public/default/topic-name-61b9697b6f087aca /
subscription-name-3afa9641ff625519
08:34:45.074 [pulsar-io-51-8] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl -
[public/default/persistent/topic-name-61b9697b6f087aca] Cursor
subscription-name-3afa9641ff625519 recovered to position 41:99999
08:34:45.074 [pulsar-io-51-8] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[public/default/persistent/topic-name-61b9697b6f087aca] Creating ledger,
metadata: {component=[109, 97, 110, 97, 103, 101, 100, 45, 108, 101, 100, 103,
101, 114], pulsar/managed-ledger=[112, 117, 98, 108, 105, 99, 47, 100, 101,
102, 97, 117, 108, 116, 47, 112, 101, 114, 115, 105, 115, 116, 101, 110, 116,
47, 116, 111, 112, 105, 99, 45, 110, 97, 109, 101, 45, 54, 49, 98, 57, 54, 57,
55, 98, 54, 102, 48, 56, 55, 97, 99, 97], pulsar/cursor=[115, 117, 98, 115, 99,
114, 105, 112, 116, 105, 111, 110, 45, 110, 97, 109, 101, 45, 51, 97, 102, 97,
57, 54, 52, 49, 102, 102, 54, 50, 53, 53, 49, 57], application=[112, 117, 108,
115, 97, 114]} - metadata ops timeout : 60 seconds
08:34:45.079 [main-EventThread] INFO
org.apache.bookkeeper.client.LedgerCreateOp - Ensemble: [127.0.0.1:3181] for
ledger: 45
08:34:45.081 [BookKeeperClientWorker-OrderedExecutor-5-0] INFO
org.apache.bookkeeper.mledger.impl.MetaStoreImpl -
[public/default/persistent/topic-name-61b9697b6f087aca]
[subscription-name-3afa9641ff625519] Updating cursor info ledgerId=45
mark-delete=41:99999
08:34:45.084 [bookkeeper-ml-workers-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl -
[public/default/persistent/topic-name-61b9697b6f087aca] Updated cursor
subscription-name-3afa9641ff625519 with ledger id 45 md-position=41:99999
rd-position=41:100000
08:34:45.084 [bookkeeper-ml-workers-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl -
[public/default/persistent/topic-name-61b9697b6f087aca] Opened new cursor:
ManagedCursorImpl{ledger=public/default/persistent/topic-name-61b9697b6f087aca,
name=subscription-name-3afa9641ff625519, ackPos=41:99999, readPos=41:100000}
08:34:45.084 [bookkeeper-ml-workers-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl -
[public/default/persistent/topic-name-61b9697b6f087aca-subscription-name-3afa9641ff625519]
Rewind from 41:0 to 41:0
08:34:45.085 [bookkeeper-ml-workers-OrderedExecutor-0-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentTopic -
[persistent://public/default/topic-name-61b9697b6f087aca] There are no
replicated subscriptions on the topic
08:34:45.085 [bookkeeper-ml-workers-OrderedExecutor-0-0] INFO
org.apache.pulsar.broker.service.persistent.PersistentTopic -
[persistent://public/default/topic-name-61b9697b6f087aca][subscription-name-3afa9641ff625519]
Created new subscription for 1
08:34:45.085 [bookkeeper-ml-workers-OrderedExecutor-0-0] INFO
org.apache.pulsar.broker.service.ServerCnx - [/172.17.0.1:40030] Created
subscription on topic persistent://public/default/topic-name-61b9697b6f087aca /
subscription-name-3afa9641ff625519
08:34:45.086 [pulsar-io-51-8] INFO
org.apache.pulsar.broker.service.ServerCnx - Closed connection from
/172.17.0.1:40030
08:34:45.086 [pulsar-io-51-8] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers
- Removed consumer
Consumer{subscription=PersistentSubscription{topic=persistent://public/default/topic-name-61b9697b6f087aca,
name=subscription-name-3afa9641ff625519}, consumerId=1,
consumerName=consumer-name-3f0be6cd39d4812b, address=/172.17.0.1:40030} with
pending 0 acks
08:34:45.087 [bookkeeper-ml-workers-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl -
[public/default/persistent/topic-name-61b9697b6f087aca-subscription-name-3afa9641ff625519]
Rewind from 41:1 to 41:0
08:34:45.187 [pulsar-io-51-9] INFO
org.apache.pulsar.broker.service.ServerCnx - New connection from
/172.17.0.1:40034
08:34:45.190 [pulsar-io-51-9] INFO
org.apache.pulsar.broker.service.ServerCnx - [/172.17.0.1:40034] Subscribing on
topic persistent://public/default/topic-name-61b9697b6f087aca /
subscription-name-3afa9641ff625519
08:34:45.190 [pulsar-io-51-9] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl -
[public/default/persistent/topic-name-61b9697b6f087aca-subscription-name-3afa9641ff625519]
Rewind from 41:0 to 41:0
08:34:45.190 [pulsar-io-51-9] INFO
org.apache.pulsar.broker.service.persistent.PersistentTopic -
[persistent://public/default/topic-name-61b9697b6f087aca] There are no
replicated subscriptions on the topic
08:34:45.191 [pulsar-io-51-9] INFO
org.apache.pulsar.broker.service.persistent.PersistentTopic -
[persistent://public/default/topic-name-61b9697b6f087aca][subscription-name-3afa9641ff625519]
Created new subscription for 1
08:34:45.191 [pulsar-io-51-9] INFO
org.apache.pulsar.broker.service.ServerCnx - [/172.17.0.1:40034] Created
subscription on topic persistent://public/default/topic-name-61b9697b6f087aca /
subscription-name-3afa9641ff625519
08:34:45.286 [pulsar-io-51-9] INFO
org.apache.pulsar.broker.service.ServerCnx - Closed connection from
/172.17.0.1:40034
08:34:45.286 [pulsar-io-51-9] INFO
org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers
- Removed consumer
Consumer{subscription=PersistentSubscription{topic=persistent://public/default/topic-name-61b9697b6f087aca,
name=subscription-name-3afa9641ff625519}, consumerId=1,
consumerName=consumer-name-3f0be6cd39d4812b, address=/172.17.0.1:40034} with
pending 64 acks
08:34:45.286 [bookkeeper-ml-workers-OrderedExecutor-0-0] INFO
org.apache.bookkeeper.mledger.impl.ManagedCursorImpl -
[public/default/persistent/topic-name-61b9697b6f087aca-subscription-name-3afa9641ff625519]
Rewind from 41:3000 to 41:2836
08:34:50.409 [pulsar-web-69-13] INFO org.eclipse.jetty.server.RequestLog -
127.0.0.1 - - [17/Sep/2020:08:34:50 +0000] "GET
/admin/v2/persistent/public/functions/coordinate/stats?getPreciseBacklog=false
HTTP/1.1" 200 1283 "-" "Pulsar-Java-v2.6.1-sn-3" 7
```
----------------------------------------------------------------
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:
us...@infra.apache.org
