You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@pulsar.apache.org by Apache Pulsar Slack <ap...@gmail.com> on 2019/07/16 09:11:03 UTC
Slack digest for #general - 2019-07-16
2019-07-15 09:35:28 UTC - Sijie Guo: Can you explain a bit about your expectation about SSO in a messaging system? That might help us understand your requirements.
----
2019-07-15 10:03:48 UTC - vikash: I have followed this doc to setup authentication in Apache pulsar standalone but we start using ./bin/pulsar-daemon start standalone <https://pulsar.apache.org/docs/en/security-token-admin/?origin_team=T5Z3B324U>
----
2019-07-15 10:04:01 UTC - vikash: but getting Error like 15:29:48.520 [pulsar-io-50-1] WARN org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:57398] Unable to authenticate
javax.naming.AuthenticationException: No anonymous role, and no authentication provider configured
----
2019-07-15 10:05:32 UTC - vikash: enabled authentication
----
2019-07-15 10:26:54 UTC - vikash: also server auto shutdown with above Exception connection refused
----
2019-07-15 11:55:21 UTC - jia zhai: Hi Vikash, This may caused by the internal client/admin(created in broker it self) also tries to connect and auth with broker.
You could try to also config these in standalone config.
```
# Authentication settings of the broker itself. Used when the broker connects to other brokers,
# either in same or other clusters
brokerClientTlsEnabled=false
brokerClientAuthenticationPlugin=
brokerClientAuthenticationParameters=
brokerClientTrustCertsFilePath=
```
----
2019-07-15 12:20:25 UTC - Glen Marchesani: @Glen Marchesani has joined the channel
----
2019-07-15 15:49:06 UTC - Glen Marchesani: Using the java client on a plain vanilla pulsar setup. I create a reader and before I read it it gets closed by the broker. Looking for any insight as to what I should do to diagnose. Noting Everything "just works" in my test bed. I am hitting this issue when wiring it into the larger app framework. I am 100% clear that the close isn't getting called by my code.
----
2019-07-15 15:49:32 UTC - Glen Marchesani: ```
11:49:17.290 | DEBUG | hermes-pool-1 | a8.hermes.server.PulsarMessageStore | receiveAsync
195029 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerStatsRecorderImpl - Starting Pulsar consumer perf with config: {
"topicNames" : [ "e6fc1bfa0fe3415d8b66445d5f56b745" ],
"topicsPattern" : null,
"subscriptionName" : "reader-4a198fe6c0",
"subscriptionType" : "Exclusive",
"receiverQueueSize" : 1000,
"acknowledgementsGroupTimeMicros" : 100000,
"maxTotalReceiverQueueSizeAcrossPartitions" : 50000,
"consumerName" : "1e14f48b-b465-4111-9640-6b6583c40d9b",
"ackTimeoutMillis" : 0,
"tickDurationMillis" : 1000,
"priorityLevel" : 0,
"cryptoFailureAction" : "FAIL",
"properties" : { },
"readCompacted" : false,
"subscriptionInitialPosition" : "Latest",
"patternAutoDiscoveryPeriod" : 1,
"regexSubscriptionMode" : "PersistentOnly",
"deadLetterPolicy" : null,
"autoUpdatePartitions" : true
}
195030 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerStatsRecorderImpl - Pulsar client config: {
"serviceUrl" : "<pulsar://localhost:6650>",
"operationTimeoutMs" : 30000,
"statsIntervalSeconds" : 60,
"numIoThreads" : 1,
"numListenerThreads" : 1,
"connectionsPerBroker" : 1,
"useTcpNoDelay" : true,
"useTls" : false,
"tlsTrustCertsFilePath" : "",
"tlsAllowInsecureConnection" : false,
"tlsHostnameVerificationEnable" : false,
"concurrentLookupRequest" : 5000,
"maxLookupRequest" : 50000,
"maxNumberOfRejectedRequestPerConnection" : 50,
"keepAliveIntervalSeconds" : 30,
"connectionTimeoutMs" : 10000
}
195031 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [e6fc1bfa0fe3415d8b66445d5f56b745][reader-4a198fe6c0] Subscribing to topic on cnx [id: 0xee841dfc, L:/127.0.0.1:52280 - R:localhost/127.0.0.1:6650]
195033 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [e6fc1bfa0fe3415d8b66445d5f56b745][reader-4a198fe6c0] Subscribed to topic on localhost/127.0.0.1:6650 -- consumer: 2
195035 [pulsar-client-io-1-1] INFO org.apache.pulsar.client.impl.ConsumerImpl - [e6fc1bfa0fe3415d8b66445d5f56b745] [reader-4a198fe6c0] Closed consumer
```
----
2019-07-15 15:49:52 UTC - Glen Marchesani: so 2ms after the subscription it gets closed...
----
2019-07-15 15:57:58 UTC - Glen Marchesani: if I turn on debug logging the close is from the broker
----
2019-07-15 16:09:28 UTC - David Kjerrumgaard: @Glen Marchesani Can you share the relevant output from the broker that shows the close?
----
2019-07-15 16:09:46 UTC - Glen Marchesani: ah good idea, I hadn't even looked at the broker side
----
2019-07-15 16:09:50 UTC - Glen Marchesani: I will get that
----
2019-07-15 16:10:08 UTC - Glen Marchesani: I will also get the logging level turned back up to make sure the close message is what I think it was
----
2019-07-15 16:13:54 UTC - Glen Marchesani: gimme 30 minutes to get it back into the state needed to give you this info, as I am actively hacking on this
----
2019-07-15 16:14:05 UTC - David Kjerrumgaard: no worries....
----
2019-07-15 16:33:37 UTC - Glen Marchesani: I don't have the client side logs saying consumer closed by broker I can track that down if needed (there are a lot of logs from the main app since I can't repro in a testbed yet), just a matter of finding the write log levels to turn on...
----
2019-07-15 16:33:44 UTC - Glen Marchesani: Here is the server side log for a single transaction
----
2019-07-15 16:33:47 UTC - Glen Marchesani: ```
12:32:32.235 [pulsar-io-50-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:56532] Subscribing on topic <persistent://public/default/e6fc1bfa0fe3415d8b66445d5f56b745> / reader-88d199a258
12:32:32.235 [pulsar-io-50-1] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [<persistent://public/default/e6fc1bfa0fe3415d8b66445d5f56b745>][reader-88d199a258] Creating non-durable subscription at msg id -1:-1:-1:-1
12:32:32.236 [pulsar-io-50-1] INFO org.apache.bookkeeper.mledger.impl.NonDurableCursorImpl - [public/default/persistent/e6fc1bfa0fe3415d8b66445d5f56b745] Created non-durable cursor read-position=6155:0 mark-delete-position=-1:-2
12:32:32.236 [pulsar-io-50-1] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [public/default/persistent/e6fc1bfa0fe3415d8b66445d5f56b745] Opened new cursor: NonDurableCursorImpl{ledger=public/default/persistent/e6fc1bfa0fe3415d8b66445d5f56b745, ackPos=-1:-2, readPos=6155:0}
12:32:32.236 [pulsar-io-50-1] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/e6fc1bfa0fe3415d8b66445d5f56b745-reader-88d199a258] Rewind from 6155:0 to 6155:0
12:32:32.236 [pulsar-io-50-1] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [<persistent://public/default/e6fc1bfa0fe3415d8b66445d5f56b745>] There are no replicated subscriptions on the topic
12:32:32.236 [pulsar-io-50-1] INFO org.apache.pulsar.broker.service.persistent.PersistentTopic - [<persistent://public/default/e6fc1bfa0fe3415d8b66445d5f56b745>][reader-88d199a258] Created new subscription for 2
12:32:32.236 [pulsar-io-50-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:56532] Created subscription on topic <persistent://public/default/e6fc1bfa0fe3415d8b66445d5f56b745> / reader-88d199a258
12:32:32.238 [pulsar-io-50-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:56532] Closing consumer: 2
12:32:32.238 [pulsar-io-50-1] INFO org.apache.pulsar.broker.service.AbstractDispatcherSingleActiveConsumer - Removing consumer Consumer{subscription=PersistentSubscription{topic=<persistent://public/default/e6fc1bfa0fe3415d8b66445d5f56b745>, name=reader-88d199a258}, consumerId=2, consumerName=f2e7a7ae-cffe-4197-8494-695ca449dff3, address=/127.0.0.1:56532}
12:32:32.238 [pulsar-io-50-1] INFO org.apache.pulsar.broker.service.persistent.PersistentSubscription - [<persistent://public/default/e6fc1bfa0fe3415d8b66445d5f56b745>][reader-88d199a258] Successfully closed subscription [NonDurableCursorImpl{ledger=public/default/persistent/e6fc1bfa0fe3415d8b66445d5f56b745, ackPos=-1:-2, readPos=6155:0}]
12:32:32.238 [pulsar-io-50-1] INFO org.apache.pulsar.broker.service.ServerCnx - [/127.0.0.1:56532] Closed consumer Consumer{subscription=PersistentSubscription{topic=<persistent://public/default/e6fc1bfa0fe3415d8b66445d5f56b745>, name=reader-88d199a258}, consumerId=2, consumerName=f2e7a7ae-cffe-4197-8494-695ca449dff3, address=/127.0.0.1:56532}
12:32:32.239 [broker-topic-workers-OrderedScheduler-4-0] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [public/default/persistent/e6fc1bfa0fe3415d8b66445d5f56b745-reader-88d199a258] Rewind from 6155:11 to 6155:0
12:32:36.145 [pulsar-web-57-11] INFO org.eclipse.jetty.server.RequestLog - 127.0.0.1 - - [15/Jul/2019:12:32:36 -0400] "GET /admin/v2/persistent/public/functions/coordinate/stats HTTP/1.1" 200 811 "-" "Pulsar-Java-v2.4.0" 1
```
----
2019-07-15 16:34:04 UTC - Glen Marchesani: noting the consumer on the client is long lived (for 100 seconds)
----
2019-07-15 16:35:14 UTC - Glen Marchesani: any assistance is appreciated
----
2019-07-15 17:12:22 UTC - David Kjerrumgaard: The consumer names don't match...... `"consumerName" : "1e14f48b-b465-4111-9640-6b6583c40d9b"` on the client, but on the broker log snippet it is different `Removing consumer Consumer{subscription=PersistentSubscription{topic=<persistent://public/default/e6fc1bfa0fe3415d8b66445d5f56b745>, name=reader-88d199a258}, consumerId=2, consumerName=f2e7a7ae-cffe-4197-8494-695ca449dff3, address=/127.0.0.1:56532}`
----
2019-07-15 17:12:43 UTC - David Kjerrumgaard: Are you sure you have the correct broker log file entries?
----
2019-07-15 17:19:48 UTC - Glen Marchesani: let me run it and capture both sides and put here
----
2019-07-15 17:20:09 UTC - Glen Marchesani: yes @David Kjerrumgaard they are different runs
+1 : David Kjerrumgaard
----
2019-07-15 17:31:05 UTC - Glen Marchesani:
----
2019-07-15 17:31:21 UTC - Glen Marchesani:
----
2019-07-15 17:32:00 UTC - Glen Marchesani: the stack trace on the client logs is properly caught and managed it is from calling Reader.hasMoreMessagesAvailable()
----
2019-07-15 17:42:03 UTC - David Kjerrumgaard: So the broker is closing the consumer immediately after the associated subscription is created, but there is not indication as to why that is the case.
----
2019-07-15 17:42:26 UTC - David Kjerrumgaard: The consumer doesn't read any messages
----
2019-07-15 17:42:38 UTC - David Kjerrumgaard: Are there any messages in the topic?
----
2019-07-15 17:42:43 UTC - Glen Marchesani: yes
----
2019-07-15 17:42:56 UTC - Glen Marchesani: I have a simple ReadTopic app that reads the topic from earliest to end
----
2019-07-15 17:43:26 UTC - Glen Marchesani: there are 18 messages in that topic
----
2019-07-15 17:43:30 UTC - David Kjerrumgaard: Any security enabled on the cluster or access policies that might be in play here?
----
2019-07-15 17:43:58 UTC - Glen Marchesani: I have not added any, I am using a vanilla install that comes from mac homebrew
----
2019-07-15 17:44:14 UTC - Glen Marchesani: looking at the the mac homebrew it just unpacks the download and runs it
----
2019-07-15 17:44:29 UTC - David Kjerrumgaard: which version of Pulsar is this 2.3.x or 2.4 ?
----
2019-07-15 17:44:44 UTC - Glen Marchesani: 2.4.0
----
2019-07-15 17:46:02 UTC - David Kjerrumgaard: Can you share the steps to reproduce the issue? I will try to do so locally and might have to file a JIRA if I can't figure out the issue
----
2019-07-15 17:51:40 UTC - Matteo Merli: @Glen Marchesani On the server side, can you also grep for the connection (eg: `127.0.0.1:61473`)? Also, could you get a tcpdump capture? That would help to quickly understand what’s happening
----
2019-07-15 17:57:38 UTC - Glen Marchesani: yes to all that...
----
2019-07-15 17:58:03 UTC - Glen Marchesani: So that is the next bit my issue only occurs inside an undertow server doing async io.
----
2019-07-15 17:58:39 UTC - Glen Marchesani: I have been trying to repro and in my simple boiler plate examples it "just works"
----
2019-07-15 18:34:15 UTC - Glen Marchesani: @David Kjerrumgaard @Matteo Merli I will get that together may not be til tomorrow, thanks for your assistance so far
+1 : Matteo Merli, David Kjerrumgaard
----
2019-07-15 21:14:29 UTC - Jacobus: @Jacobus has joined the channel
----
2019-07-15 21:58:49 UTC - Victor Siu: I have a bad message in a topic and one of my sink subscriptions keeps reading it and throwing an exception, it looks like the message gets retried. What’s the best way to deal with removing this message from the topic?
----
2019-07-15 21:59:23 UTC - Victor Siu: Short of pushing additional code changes
----
2019-07-15 22:00:51 UTC - Matteo Merli: there are 2 options:
1. Manually skip the bad message `pulsar-admin topics skip $TOPIC --subscription $SUBSCRIPTION --count 1`
2. Use Dead-letter queue to automatically route messages (requires configuration in the consumer)
----
2019-07-15 22:35:24 UTC - Victor Siu: I tried 1 and it didn’t seem to be working but now that I think about it, maybe there were just other messages that were getting mixed in since it was processing a bunch of messages.
If I updated a function with a dead-letter queue would failed messages get moved over there as soon as we set up the dead-letter-topic?
----
2019-07-15 23:18:06 UTC - Devin G. Bost: Right now, we're (Victor and the team are) getting 500's when we try to get status on anything, so it seems like we killed the service. We restarted the brokers, and we're still getting 500's.
----
2019-07-15 23:18:59 UTC - Devin G. Bost: It's not clear what killed it. We were just trying to get past the bad message.
We're still on 2.3.2 though. We haven't updated this cluster to 2.4.0 yet.
----
2019-07-15 23:21:15 UTC - Jerry Peng: What exception is getting thrown?
----
2019-07-15 23:22:06 UTC - Jerry Peng: a Pulsar internal exception or user code exception?
----
2019-07-15 23:25:46 UTC - Victor Siu: A user code exception for the bad message is the thing I’m trying to fix but the 500 is a pulsar exception as far as I can tell
----
2019-07-15 23:26:14 UTC - Thor Sigurjonsson: FYI: That cluster is on 2.4.0-streamlio-24
----
2019-07-15 23:26:33 UTC - Devin G. Bost: Oh, I did not realize we updated it already.
----
2019-07-15 23:26:33 UTC - Victor Siu: When I run a pulsar-admin functions status… command
----
2019-07-15 23:26:58 UTC - Devin G. Bost: @Victor Siu Was it happening with just one function or with others as well?
----
2019-07-15 23:27:09 UTC - Victor Siu: It’s happened on multiple functions
----
2019-07-15 23:27:16 UTC - Jerry Peng: thats expected if the function is crashing
----
2019-07-15 23:27:30 UTC - Jerry Peng: shouldn’t for other functions
----
2019-07-15 23:32:44 UTC - Victor Siu: Sorry I should clarify a little more. The behavior I’m seeing is the sink that’s getting the bad messages returns a status as expected but it shows a bunch of exceptions in the `latestSinkExceptions` part of the status. This other function which is a filter on some data hasn’t changed for while but it may or may not be throwing and exception.
----
2019-07-15 23:33:16 UTC - Victor Siu: So for functions if it’s throwing exceptions we won’t be able to run a status on them?
----
2019-07-16 01:26:37 UTC - Jerry Peng: should return something like:
```
{
"numInstances" : 1,
"numRunning" : 0,
"instances" : [ {
"instanceId" : 0,
"status" : {
"running" : false,
"error" : "UNAVAILABLE: io exception",
"numRestarts" : 0,
"numReceivedFromSource" : 0,
"numSystemExceptions" : 0,
"latestSystemExceptions" : [ ],
"numSourceExceptions" : 0,
"latestSourceExceptions" : [ ],
"numWritten" : 0,
"lastReceivedTime" : 0,
"workerId": "local-8080"
}
} ]
}
```
----
2019-07-16 03:59:29 UTC - Terry Wei: Say like if I am running a SSO server which has OIDC and OAuth2 support, can I protect the Pulsar topics by configuring something with pulsar admin? like telling pulsar where is my SSO server and what protocol SSO supports, then in turn I can config some rules in SSO server so that certain user can have different lvl of authentication and authorisation to access the pulsar resources.
----
2019-07-16 05:41:48 UTC - Devin G. Bost: What does it mean if a `get` command on a source gives a 500 error but it says that it's running fine when you run `status` on it?
----
2019-07-16 05:43:24 UTC - Jerry Peng: I would check broker/worker logs
----
2019-07-16 05:43:48 UTC - Jerry Peng: The get request might I have been executed by a worker that is faulty
----
2019-07-16 05:43:52 UTC - Devin G. Bost: Hi Jerry, thanks.
----
2019-07-16 05:53:02 UTC - Devin G. Bost: All I found in the logs was this:
----
2019-07-16 05:54:32 UTC - Devin G. Bost: However, that might have been around when I restarted the source.
----
2019-07-16 05:59:15 UTC - Jerry Peng: Restarting the source would cause an exception like this
----
2019-07-16 06:34:33 UTC - Devin G. Bost: Okay. Thanks for the information.
----