You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@pulsar.apache.org by GitBox <gi...@apache.org> on 2020/05/05 04:31:24 UTC
[GitHub] [pulsar-client-go] jinfengnarvar opened a new issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
jinfengnarvar opened a new issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239
#### Expected behavior
Sending large number of large payloads via `Producer.Send()` shouldn't panic/crash
#### Actual behavior
Need some insights from you guys if this rings any bell or not. We've been using pure golang client for a few weeks now with good results until we just recently onboarded a new customer, who sends in large order files each of which contains many large records.
Typically record after protobuf encoding is about 150KB to 300KB. And we have millions of these records. Although the send is called in a single thread right now, when we start rapidly calling Send, our logs suddenly shows this:
```
.......
.......
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:46Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:47Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-05T03:06:48Z","severity":"INFO","message":"Error reading from connection"}
panic: send on closed channel
goroutine 3105 [running]:
github.com/apache/pulsar-client-go/pulsar/internal.(*rpcClient).Request.func1(0xc001e3bc00, 0x0, 0x0)
/go/pkg/mod/github.com/apache/pulsar-client-go@v0.0.0-20200316114055-4dc7855f99dc/pulsar/internal/rpc_client.go:97 +0xb6
github.com/apache/pulsar-client-go/pulsar/internal.(*connection).handleResponse(0xc0057945a0, 0x65, 0xc001e3bc00)
/go/pkg/mod/github.com/apache/pulsar-client-go@v0.0.0-20200316114055-4dc7855f99dc/pulsar/internal/connection.go:493 +0xb3
github.com/apache/pulsar-client-go/pulsar/internal.(*connection).internalReceivedCommand(0xc0057945a0, 0xc001e3bc00, 0x0, 0x0)
/go/pkg/mod/github.com/apache/pulsar-client-go@v0.0.0-20200316114055-4dc7855f99dc/pulsar/internal/connection.go:403 +0x2e4
github.com/apache/pulsar-client-go/pulsar/internal.(*connection).run(0xc0057945a0)
/go/pkg/mod/github.com/apache/pulsar-client-go@v0.0.0-20200316114055-4dc7855f99dc/pulsar/internal/connection.go:325 +0x304
github.com/apache/pulsar-client-go/pulsar/internal.(*connection).start.func1(0xc0057945a0)
/go/pkg/mod/github.com/apache/pulsar-client-go@v0.0.0-20200316114055-4dc7855f99dc/pulsar/internal/connection.go:195 +0x59
created by github.com/apache/pulsar-client-go/pulsar/internal.(*connection).start
/go/pkg/mod/github.com/apache/pulsar-client-go@v0.0.0-20200316114055-4dc7855f99dc/pulsar/internal/connection.go:192 +0x3f
```
#### Steps to reproduce
Not sure how this can be repro'ed on your side. I'm reaching out to your rep's slack channel within our company to investigate as well.
#### System configuration
**Pulsar version**: github.com/apache/pulsar-client-go v0.0.0-20200316114055-4dc7855f99dc
**Go version**: 1.12
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] wolfstudy edited a comment on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
wolfstudy edited a comment on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-625238240
> connection closed...; reconnecting to broker....;
This means that the current connection between the client and the broker is closed, and the client attempts to establish a connection with the broker again within the `connection timeout`.
> {"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Connection closed"}
The log level is `INFO`, this means that the user program triggered the go client to close the current connection. When the go client receives the `connectionClosed`, it will reconnect to the broker.
```
func (c *connection) internalWriteData(data []byte) {
c.log.Debug("Write data: ", len(data))
if _, err := c.cnx.Write(data); err != nil {
c.log.WithError(err).Warn("Failed to write on connection")
c.Close()
}
}
```
So the root of the problem is the failure of c.cnx.Write (data), can you open the debug log and see what the data format is when an error occurs?
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] wolfstudy commented on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
wolfstudy commented on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-624414540
I will try to reproduce the issue, you are also welcome to provide a reproducible code
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] wolfstudy edited a comment on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
wolfstudy edited a comment on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-625238240
> connection closed...; reconnecting to broker....;
This means that the current connection between the client and the broker is closed, and the client attempts to establish a connection with the broker again within the `connection timeout`.
> {"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Connection closed"}
The log level is `INFO`, this means that the user program triggered the go client to close the current connection. When the go client receives the `connectionClosed`, it will reconnect to the broker.
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] wolfstudy commented on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
wolfstudy commented on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-625268370
> Seems like there is some racing condition in the client caused this panic.
Yes, agree with you, even if we checked the size of the message, the error `panic: send on closed channel` should not happen, so we may not close the channel properly somewhere.
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] wolfstudy closed issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
wolfstudy closed issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] wolfstudy edited a comment on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
wolfstudy edited a comment on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-625238240
> connection closed...; reconnecting to broker....;
This means that the current connection between the client and the broker is closed, and the client attempts to establish a connection with the broker again within the `connection timeout`.
> {"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Connection closed"}
The log level is `INFO`, this means that the user program triggered the go client to close the current connection. When the go client receives the `connectionClosed`, it will reconnect to the broker.
```
func (c *connection) internalWriteData(data []byte) {
c.log.Debug("Write data: ", len(data))
if _, err := c.cnx.Write(data); err != nil {
c.log.WithError(err).Warn("Failed to write on connection")
c.Close()
}
}
```
So the root of the problem is the failure of `c.cnx.Write (data)`, can you open the debug log and see what the data format is when an error occurs?
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] wolfstudy commented on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
wolfstudy commented on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-625263419
> Update, enabled more logging and found that the payload we're sending right before the crash occurred is 27MB big!!
By default, the maximum message allowed by the broker is 5MB, as follows:
```
# Max size of messages.
maxMessageSize=5242880
```
The best way is that we should check the size of the message in the go client, if it exceeds 5MB we will not process it.
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] jinfengnarvar commented on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
jinfengnarvar commented on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-624783201
Update, enabled more logging and found that the payload we're sending right before the crash occurred is 27MB big!!
That object is incorrect, shouldn't be that big.
That said, do we want to make the pulsar go client more robust to fail us and return us some err, instead of panic/crash?
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] wolfstudy edited a comment on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
wolfstudy edited a comment on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-625238240
> connection closed...; reconnecting to broker....;
This means that the current connection between the client and the broker is closed, and the client attempts to establish a connection with the broker again within the `connection timeout`.
> {"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Connection closed"}
The log level is `INFO`, this means that the user program triggered the go client to close the current connection of the consumer. When the go client receives the `connectionClosed`, it will reconnect to the broker.
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] wolfstudy commented on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
wolfstudy commented on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-624414306
Thanks @jinfengnarvar feedback, It seems that we did not close the channel properly somewhere, causing the application to continue writing data to a closed channel.
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] wolfstudy commented on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
wolfstudy commented on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-625238240
> connection closed...; reconnecting to broker....;
This means that the current connection between the client and the broker is closed, and the client attempts to establish a connection with the broker again within the `connection timeout`.
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] jinfengnarvar commented on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
jinfengnarvar commented on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-624725813
A bit more finding after having placing some logs in our code:
```
func sendOrderMessage(
ctx *msgProcessor.MsgContext, key string, orderMessage order.QueueOrderMessage,
recordIndex, aggregatedRecordIndex int) error {
pbBytes, _ := proto.Marshal(&orderMessage)
if file1022LogOn(ctx, false) {
nlog.Infof("cabelas sending pulsar: raw record index: %d, aggregated record index: %d, bytes: %d, key: %s",
recordIndex + 1, aggregatedRecordIndex + 1, len(pbBytes), key)
}
defer func() {
if p := recover(); p != nil {
nlog.Infof("crashed")
nlog.Infof(" - raw record index: %d", recordIndex + 1)
nlog.Infof(" - aggregated record index: %d", aggregatedRecordIndex + 1)
nlog.Infof(" - bytes: %d", len(pbBytes))
nlog.Infof(" - key: %s", key)
nlog.Infof(" - payload: %s", jsonutils.BestEffortJsonMarshal(orderMessage))
// re-panic
panic(p)
}
}()
err := ctx.OutputClient.Send(
context.Background(),
npulsar.NewPulsarProducerMessage(pbBytes, key))
if err != nil {
...
...
```
Notes:
- because we have many lines, so `file1022LogOn` is a probability logging decider so we don't log out too much. but it is irrelevant here since in the panic recovery we do always log out.
Now the logging we've obtained:
```
{"timestamp":"2020-05-06T15:02:53Z","severity":"INFO","message":"cabelas sending pulsar: raw record index: 34572, aggregated record index: 458, bytes: 19008, key: 250473543"}
{"timestamp":"2020-05-06T15:02:57Z","severity":"INFO","message":"cabelas sending pulsar: raw record index: 37516, aggregated record index: 516, bytes: 3953, key: 250473623"}
{"timestamp":"2020-05-06T15:03:03Z","severity":"INFO","message":"cabelas sending pulsar: raw record index: 41463, aggregated record index: 588, bytes: 9694, key: 250473719"}
{"timestamp":"2020-05-06T15:03:03Z","severity":"INFO","message":"cabelas sending pulsar: raw record index: 41467, aggregated record index: 589, bytes: 5480, key: 250473720"}
{"timestamp":"2020-05-06T15:03:04Z","severity":"INFO","message":"cabelas sending pulsar: raw record index: 42743, aggregated record index: 603, bytes: 144220, key: 250473740"}
{"timestamp":"2020-05-06T15:03:05Z","severity":"INFO","message":"cabelas sending pulsar: raw record index: 43162, aggregated record index: 613, bytes: 8613, key: 250473756"}
{"timestamp":"2020-05-06T15:03:08Z","severity":"INFO","message":"cabelas sending pulsar: raw record index: 45655, aggregated record index: 631, bytes: 14079, key: 250473779"}
{"timestamp":"2020-05-06T15:03:16Z","severity":"INFO","message":"cabelas sending pulsar: raw record index: 51348, aggregated record index: 703, bytes: 14795, key: 250473874"}
....
{"timestamp":"2020-05-06T15:03:26Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-06T15:03:26Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-06T15:03:26Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-06T15:03:26Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-06T15:03:26Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-06T15:03:26Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-06T15:03:26Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-06T15:03:26Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-06T15:03:26Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-06T15:03:26Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-06T15:03:26Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Error reading from connection"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Connecting to broker"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"TCP connection established"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Connection is ready"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Resending 1 pending batches"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnected producer to broker"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"WARNING","message":"Failed to write on connection"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Connection closed"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"WARNING","message":"Connection was closed"}
{"timestamp":"2020-05-06T15:03:27Z","severity":"INFO","message":"Reconnecting to broker in 100ms"}
panic: send on closed channel
goroutine 834 [running]:
github.com/apache/pulsar-client-go/pulsar/internal.(*rpcClient).Request.func1(0xc0028fa1c0, 0x0, 0x0)
/go/pkg/mod/github.com/apache/pulsar-client-go@v0.0.0-20200316114055-4dc7855f99dc/pulsar/internal/rpc_client.go:97 +0xb6
github.com/apache/pulsar-client-go/pulsar/internal.(*connection).handleResponse(0xc0052b6b40, 0x1e, 0xc0028fa1c0)
/go/pkg/mod/github.com/apache/pulsar-client-go@v0.0.0-20200316114055-4dc7855f99dc/pulsar/internal/connection.go:493 +0xb3
```
As you can see:
- At 1% logging rate, those logged payloads are not big, the biggest is 140kb.
- Apparently the crash isn't in our send goroutine, because we would otherwise capture the panic and logged out but we didn't. So the crash is inside pulsar client somewhere.
- I'm really suspecting this has something to do with capacity?
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] jinfengnarvar commented on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
jinfengnarvar commented on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-624640208
@wolfstudy thx. i'm also trying to find a (more) deterministic way to repro it - right now it only occurs in our prod env service that processes multiple large files at the same time. crash occurs frequently but not in a deterministic way.
also i'm wondering if anyone has any insight of what's the repeated blocks of "failed to write...; connection closed...; reconnecting to broker....;" failure logs indicate? Apparently these logs are from within the pulsar go client, you guys happen to use `github.com/sirupsen/logrus` as well so we were able to catch it and dump it out.
my question is we're in the midst of writing to producer partitions, and what could usually cause the connection sever? broker overloaded (due to volume or payload size?) Anything on the pulsar server side can be configured to reveal the connection drop failure reason?
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] wolfstudy edited a comment on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
wolfstudy edited a comment on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-625263419
> Update, enabled more logging and found that the payload we're sending right before the crash occurred is 27MB big!!
By default, the maximum message allowed by the broker is 5MB, as follows:
```
# Max size of messages.
maxMessageSize=5242880
```
The best way is that we should check the size of the message in the go client, if it exceeds 5MB we will not process it. Follow the java client logic: https://github.com/apache/pulsar/blob/master/pulsar-client/src/main/java/org/apache/pulsar/client/impl/ClientCnx.java#L294-L302
----------------------------------------------------------------
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:
users@infra.apache.org
[GitHub] [pulsar-client-go] jinfengnarvar commented on issue #239: panic during rapid send of many large-sized payloads: "panic: send on closed channel"
Posted by GitBox <gi...@apache.org>.
jinfengnarvar commented on issue #239:
URL: https://github.com/apache/pulsar-client-go/issues/239#issuecomment-625265379
> > Update, enabled more logging and found that the payload we're sending right before the crash occurred is 27MB big!!
>
> By default, the maximum message allowed by the broker is 5MB, as follows:
>
> ```
> # Max size of messages.
> maxMessageSize=5242880
> ```
>
> The best way is that we should check the size of the message in the go client, if it exceeds 5MB we will not process it.
Yes having a size check in the client library is good. But I'm still concerned about the crash. Even without the check, when we (our code) ask the client to send something illegal (in this case an over-the-limit payload), it should fail gracefully with no panic. Seems like there is some racing condition in the client caused this panic.
----------------------------------------------------------------
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:
users@infra.apache.org