Php-rdkafka: SIGSEGV - core dumped if setDrMsgCb and cluster is not available

[PopovAnatolii]

• PHP version: 7.0.27
• librdkafka version: v1.1.0
• php-rdkafka version:3.1.0

If brokers cluster is down and brokers more than one (['kafka:9091', 'kafka:9093', ....]), time to time i have in my php-fpm.log records like this:

child 1334050 exited on signal 11 (SIGSEGV - core dumped)

But, if i remove setDrMsgCb or brokers cluster is ok or broker just one (['kafka:9091']), problem is gone.

Config:

'queue.buffering.max.ms' => 1,
'message.timeout.ms' => 1000,

Parts of my code:

$config->setDrMsgCb($this->getDeliveredCallback());
.....

private function getDeliveredCallback(): \Closure
{
        return function (\RdKafka $kafka, Message $message) {
            try {
                $loggerMessageContext = $this->getLoggerContextByMessage($message);

                if ($errorCode = $message->err) {
                    $errorMessage = 'Sending to Kafka error' . rd_kafka_err2str($errorCode);

                    $this->log(LogLevel::ALERT, $errorMessage,  $loggerMessageContext);
                }

                if (!$this->onlyErrorsLogging) {
                    $this->log(LogLevel::DEBUG, 'Sent to Kafka',  $loggerMessageContext);
                }
            } catch (\Throwable $throwable) {

            }
        };
}

.....

$timeout = $timeout ?: $this->flushTimeout ?: self::DEFAULT_FLUSH_TIMEOUT;

this->getProducer()->poll(0);

$endTime = microtime(true) + $timeout / 1000;
$remainingTime = $timeout;

while ($this->getProducer()->getOutQLen() > 0 && $remainingTime > 0) {
    $this->getProducer()->poll($remainingTime);

    $remainingTime = (int) (($endTime - microtime(true)) * 1000);
}

librdkafka log:

in.features gzip,snappy,ssl,sasl,regex,lz4,sasl_gssapi,sasl_plain,sasl_scram,plugins,sasl_oauthbearer, GCC GXX PKGCONFIG INSTALL GNULD LDS LIBDL PLUGINS ZLIB SSL SASL_CYRUS HDRHISTOGRAM SNAPPY SOCKEM SASL_SCRAM SASL_OAUTHBEARER CRC32C_HW, debug 0xffff)"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.906|WAKEUPFD|rdkafka#producer-1| [thrd:app]:****:1/bootstrap: Enabled low-latency ops queue wake-ups"
[02-Jul-2019 19:25:01] WARNING: [pool ****7] child 1337098 said into stderr: "%7|1562084701.906|BROKER|rdkafka#producer-1| [thrd:app]: ****:1/bootstrap: Added new broker with NodeId -1"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.906|WAKEUPFD|rdkafka#producer-1| [thrd:app]: ****:1/bootstrap: Enabled low-latency ops queue wake-ups"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.906|BRKMAIN|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Enter main broker thread"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.906|BROKER|rdkafka#producer-1| [thrd:app]: ****:1/bootstrap: Added new broker with NodeId -1"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.906|WAKEUPFD|rdkafka#producer-1| [thrd:app]: ****:1/bootstrap: Enabled low-latency ops queue wake-ups"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.906|BROKER|rdkafka#producer-1| [thrd:app]: ****:1/bootstrap: Added new broker with NodeId -1"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.906|WAKEUPFD|rdkafka#producer-1| [thrd:app]: ****:1/bootstrap: Enabled low-latency ops queue wake-ups"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.906|BROKER|rdkafka#producer-1| [thrd:app]: ****:1/bootstrap: Added new broker with NodeId -1"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.906|WAKEUPFD|rdkafka#producer-1| [thrd:app]: ****:1/bootstrap: Enabled low-latency ops queue wake-ups"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.906|BRKMAIN|rdkafka#producer-1| [thrd::0/internal]: :0/internal: Enter main broker thread"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.906|BRKMAIN|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Enter main broker thread"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.907|BROKER|rdkafka#producer-1| [thrd:app]: ****:1/bootstrap: Added new broker with NodeId -1"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.907|CONNECT|rdkafka#producer-1| [thrd:app]: ****:1/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.907|BRKMAIN|rdkafka#producer-1| [thrd:****:1/bootstrap]:****:1/bootstrap: Enter main broker thread"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.907|TOPIC|rdkafka#producer-1| [thrd:app]: New local topic: ****"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.907|TOPPARNEW|rdkafka#producer-1| [thrd:app]: NEW **** [-1] 0x1ed01d0 (at rd_kafka_topic_new0:393)"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.907|CONNECT|rdkafka#producer-1| [thrd:app]: Not selecting any broker for cluster connection: still suppressed for 49ms: leader query"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.907|CONNECT|rdkafka#producer-1| [thrd:app]: Not selecting any broker for cluster connection: still suppressed for 49ms: leader query"
[02-Jul-2019 19:25:01] WARNING: [pool *** child 1337098 said into stderr: "%7|1562084701.907|METADATA|rdkafka#producer-1| [thrd:app]: Skipping metadata refresh of 1 topic(s): no usable brokers"
[02-Jul-2019 19:25:01] WARNING: [pool ***] child 1337098 said into stderr: "%7|1562084701.907|BRKMAIN|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Enter main broker thread"
[02-Jul-2019 19:25:01] WARNING: [pool ***] child 1337098 said into stderr: "%7|1562084701.907|BRKMAIN|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Enter main broker thread"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.907|CONNECT|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Received CONNECT op"
[02-Jul-2019 19:25:01] WARNING: [pool ***] child 1337098 said into stderr: "%7|1562084701.907|STATE|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Broker changed state INIT -> TRY_CONNECT"
[02-Jul-2019 19:25:01] WARNING: [pool ***] child 1337098 said into stderr: "%7|1562084701.907|BROADCAST|rdkafka#producer-1| [thrd:****:1/bootstrap]: Broadcasting state change"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.907|CONNECT|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: broker in state TRY_CONNECT connecting"
[02-Jul-2019 19:25:01] WARNING: [pool ***] child 1337098 said into stderr: "%7|1562084701.907|STATE|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Broker changed state TRY_CONNECT -> CONNECT"
[02-Jul-2019 19:25:01] WARNING: [pool ***] child 1337098 said into stderr: "%7|1562084701.907|BROADCAST|rdkafka#producer-1| [thrd:****:1/bootstrap]: Broadcasting state change"
[02-Jul-2019 19:25:01] WARNING: [pool****] child 1337098 said into stderr: "%7|1562084701.908|CONNECT|rdkafka#producer-1| [thrd:****:1/bootstrap]: s****:1/bootstrap: Connecting to ipv4#10.61.145.230:1 (plaintext) with socket 26"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.908|BROKERFAIL|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: failed: err: Local: Broker transport failure: (errno: Connection refused)"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.909|STATE|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Broker changed state CONNECT -> DOWN"
[02-Jul-2019 19:25:01] WARNING: [pool ***] child 1337098 said into stderr: "%7|1562084701.909|BROADCAST|rdkafka#producer-1| [thrd:****:1/bootstrap]: Broadcasting state change"
[02-Jul-2019 19:25:01] WARNING: [pool ***] child 1337098 said into stderr: "%7|1562084701.909|BUFQ|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Purging bufq with 0 buffers"
[02-Jul-2019 19:25:01] WARNING: [pool ***] child 1337098 said into stderr: "%7|1562084701.909|BUFQ|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Purging bufq with 0 buffers"
[02-Jul-2019 19:25:01] WARNING: [pool ***] child 1337098 said into stderr: "%7|1562084701.909|BUFQ|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Updating 0 buffers on connection reset"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.909|STATE|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Broker changed state DOWN -> INIT"
[02-Jul-2019 19:25:01] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084701.909|BROADCAST|rdkafka#producer-1| [thrd:****:1/bootstrap]: Broadcasting state change"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.906|NOINFO|rdkafka#producer-1| [thrd:main]: Topic ***** metadata information unknown"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.906|NOINFO|rdkafka#producer-1| [thrd:main]: Topic **** partition count is zero: should refresh metadata"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.906|TIMEOUT|rdkafka#producer-1| [thrd:main]: ****: 1 message(s) timed out"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.906|CONNECT|rdkafka#producer-1| [thrd:main]: ****:1/bootstrap: Selected for cluster connection: refresh unavailable topics (broker has 0 connection attempt(s))"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.906|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: refresh unavailable topics"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.906|METADATA|rdkafka#producer-1| [thrd:main]: Skipping metadata refresh of 1 topic(s): no usable brokers"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.906|CONNECT|rdkafka#producer-1| [thrd:main]: Not selecting any broker for cluster connection: still suppressed for 49ms: no cluster connection"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.906|CONNECT|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Received CONNECT op"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.906|STATE|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Broker changed state INIT -> TRY_CONNECT"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.906|BROADCAST|rdkafka#producer-1| [thrd:****:1/bootstrap]: Broadcasting state change"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.906|CONNECT|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: broker in state TRY_CONNECT connecting"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.906|STATE|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Broker changed state TRY_CONNECT -> CONNECT"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.906|BROADCAST|rdkafka#producer-1| [thrd:****:1/bootstrap]: Broadcasting state change"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.907|CONNECT|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Connecting to ipv4#10.61.145.226:1 (plaintext) with socket 26"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.907|BROKERFAIL|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: failed: err: Local: Broker transport failure: (errno: Connection refused)"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.907|STATE|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Broker changed state CONNECT -> DOWN"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.907|BROADCAST|rdkafka#producer-1| [thrd:****:1/bootstrap]: Broadcasting state change"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.907|BUFQ|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Purging bufq with 0 buffers"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.907|BUFQ|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Purging bufq with 0 buffers"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.907|BUFQ|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Updating 0 buffers on connection reset"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.907|STATE|rdkafka#producer-1| [thrd:****:1/bootstrap]: ****:1/bootstrap: Broker changed state DOWN -> INIT"
[02-Jul-2019 19:25:02] WARNING: [pool ****] child 1337098 said into stderr: "%7|1562084702.907|BROADCAST|rdkafka#producer-1| [thrd:****:1/bootstrap]: Broadcasting state change"
[02-Jul-2019 19:25:03] WARNING: [pool ****] child 1337098 exited on signal 11 (SIGSEGV - core dumped) after 1539.237725 seconds from start

[PopovAnatolii]

with librdkafka v0.11.6 problem is gone

[Steveb-p]

Thanks @PopovAnatolii, it probably is a similar thing to the one related to producev method. I'll give it a look in the evening, unless someone does it before me ;)

[PopovAnatolii]

@Steveb-p, i didn't use producev.

$topic->produce(
            RD_KAFKA_PARTITION_UA,
            0,
            json_encode($message),
            $key
        );

[PopovAnatolii]

@Steveb-p with php-rdkafka 3.1.1 reproduced..

[Steveb-p]

@Steveb-p with php-rdkafka 3.1.1 reproduced..

@Steveb-p, i didn't use producev.

I was just referencing a similar issue that occured for that particular method (#221), which was stemming from a NULL being passed to a function of librdkafka instead of a real pointer. In versions below 1.0.0 of librdkafka that pointer was not used, while in 1.0.0 it started to - causing a segfault. A similar case might happen here.

[Steveb-p]

I've taken a quick look, but the code that is related to setting the callback function is a lot more complex (at least for my mediocre at best skill level in C and PHP extensions). Seems that setStatsCb might be affected as well, considering that they are vaguely similar.

It might take me a while to diagnose the problem, but I'll try during the weekend if nothing else.

[nick-zh]

@Steveb-p were you able to find out anything?

[Steveb-p]

@Steveb-p were you able to find out anything?

Unfortunately the code that is relevant to this proved to be completely out of my league in terms of C programming. I'm still reading about PHP extension API and so on, so I doubt I'll do anything meaningful with this in the near future :disappointed:

[nick-zh]

@Steveb-p thx for the feedback. I might give it a go as well, but probably i will be unsuccessful as well :sweat_smile:

[Steveb-p]

@nick-zh I've seen your PR's and I'm trying to learn from them. There was some similar code in one of those, so you actually might be successful.

[nick-zh]

I tried to reproduce this with:
PHP: 7.0.33
librdkafka: 1.1.0
rdkafka: 3.1.2
OS: alpine3.8

From your code snippets, i created this short script to represent your logic:

use RdKafka\Conf;
use RdKafka\Message;
use RdKafka\Producer;
use RdKafka\TopicConf;

function getDeliveryCb() {
    return function (\RdKafka $kafka, Message $message) {
        if (0 === $message->err) {
            //echo 'Sucesssfully sent!' . "\n";
        } else {
            echo 'Sending to Kafka error' . rd_kafka_err2str($message->err) . "\n";
        }
    };
}

$conf = new Conf();
$timeout = 1000;

$message = 'test';
$conf->setDrMsgCb(getDeliveryCb());

$conf->set('queue.buffering.max.ms', '1');
$conf->set('message.timeout.ms', '1000');

$producer = new Producer($conf);
$producer->setLogLevel(LOG_DEBUG);
$producer->addBrokers('kafka:9095,kafka:9096');

// Set the topic configuration:
$topicConfig = new TopicConf();
$topic = $producer->newTopic('test', $topicConfig);

while(true) {
    $topic->produce(RD_KAFKA_PARTITION_UA, 0, 'test');
    $producer->poll(0);

    $endTime = microtime(true) + $timeout / 1000;
    $remainingTime = $timeout;

    while ($producer->getOutQLen() > 0 && $remainingTime > 0) {
        $producer->poll($remainingTime);

        $remainingTime = (int) (($endTime - microtime(true)) * 1000);
    }
}

In my setup kafka:9096 was never available and i started and stopped kafka:9095 multiple times.
I was unable to reproduce the SIGSEV this way.
@PopovAnatolii maybe i am missing something in my example script i used? Or what kind of timeframe are we talking about until the SIGSEV occurs?