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.
----
