1.4.4: test suite is failing

[kloczek]

Read the FAQ first: https://github.com/edenhill/librdkafka/wiki/FAQ

+ /usr/bin/make -O -j48 V=1 VERBOSE=1 -C x86_64-redhat-linux-gnu test
make: Entering directory '/home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/x86_64-redhat-linux-gnu'
Running tests...
/usr/bin/ctest --force-new-ctest-process
Test project /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/x86_64-redhat-linux-gnu
    Start 1: RdKafkaTestInParallel
1/3 Test #1: RdKafkaTestInParallel ............Child killed***Exception:  26.10 sec
    Start 2: RdKafkaTestSequentially
2/3 Test #2: RdKafkaTestSequentially ..........Child killed***Exception:  38.77 sec
    Start 3: RdKafkaTestBrokerLess
3/3 Test #3: RdKafkaTestBrokerLess ............***Failed   65.60 sec

0% tests passed, 3 tests failed out of 3

Total Test time (real) = 130.49 sec

The following tests FAILED:
          1 - RdKafkaTestInParallel (Child killed)
          2 - RdKafkaTestSequentially (Child killed)
          3 - RdKafkaTestBrokerLess (Failed)
Errors while running CTest
make: *** [Makefile:153: test] Error 8
make: Leaving directory '/home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/x86_64-redhat-linux-gnu'

Checklist

IMPORTANT: We will close issues where the checklist has not been completed.

Please provide the following information:

• [x] librdkafka version (release number or git tag): 1.4.4
• [ ] Apache Kafka version: <REPLACE with e.g., 0.10.2.3>
• [ ] librdkafka client configuration: <REPLACE with e.g., message.timeout.ms=123, auto.reset.offset=earliest, ..>
• [ ] Operating system: <REPLACE with e.g., Centos 5 (x64)>
• [ ] Provide logs (with debug=.. as necessary) from librdkafka
• [ ] Provide broker log excerpts
• [ ] Critical issue

[edenhill]

The CMake build is not officially supported but maintained by the community. If individual tests are failing please provide the test output.

[kloczek]

OK but please be aware cmake it is only civilised build framework available in the librdkafka tree which allows use LTO and other features on build stage without sitting upside down on the chair. I think that it would be good stop using custom build framework and focus only cmake. Here is Testing/Temporary/LastTest.log

[tkloczko@barrel Temporary]$ cat LastTest.log
Start testing: Jul 09 12:46 BST
----------------------------------------------------------
1/3 Testing: RdKafkaTestInParallel
1/3 Test: RdKafkaTestInParallel
Command: "/home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/x86_64-redhat-linux-gnu/tests/test-runner" "-p5"
Directory: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/x86_64-redhat-linux-gnu/tests
"RdKafkaTestInParallel" start time: Jul 09 12:46 BST
Output:
----------------------------------------------------------
[<MAIN>                      /  0.000s] Test config file test.conf not found
[<MAIN>                      /  0.000s] Setting test timeout to 10s * 1.0
[<MAIN>                      /  0.000s] Git version: HEAD
[<MAIN>                      /  0.000s] Broker version: 2.4.0.0 (2.4.0.0)
[<MAIN>                      /  0.000s] Tests to run : all
[<MAIN>                      /  0.000s] Test mode    : bare
[<MAIN>                      /  0.000s] Test scenario: default
[<MAIN>                      /  0.000s] Test filter  : no filter
[<MAIN>                      /  0.000s] Test timeout multiplier: 2.7
[<MAIN>                      /  0.000s] Action on test failure: continue other tests
[<MAIN>                      /  0.000s] Current directory: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/x86_64-redhat-linux-gnu/tests
[<MAIN>                      /  0.000s] Setting test timeout to 30s * 2.7
[<MAIN>                      /  0.001s] Too many tests running (5 >= 5): postponing 0005_order start...
[0002_unkpart                /  0.000s] ================= Running test 0002_unkpart =================
[0002_unkpart                /  0.000s] ==== Stats written to file stats_0002_unkpart_4297257897208849021.json ====
[0002_unkpart                /  0.000s] do_test_unkpart
[0001_multiobj               /  0.000s] ================= Running test 0001_multiobj =================
[0001_multiobj               /  0.000s] ==== Stats written to file stats_0001_multiobj_5469882955236730271.json ====
[0001_multiobj               /  0.000s] Creating and destroying 5 kafka instances
[0002_unkpart                /  0.000s] Test config file test.conf not found
[0002_unkpart                /  0.000s] Setting test timeout to 10s * 2.7
[0001_multiobj               /  0.000s] Test config file test.conf not found
[0001_multiobj               /  0.000s] Setting test timeout to 30s * 2.7
[0001_multiobj               /  0.000s] Using topic "rdkafkatest_0001"
[0000_unittests              /  0.000s] ================= Running test 0000_unittests =================
[0000_unittests              /  0.000s] ==== Stats written to file stats_0000_unittests_4056417013279455890.json ====
[0003_msgmaxsize             /  0.000s] ================= Running test 0003_msgmaxsize =================
[0003_msgmaxsize             /  0.000s] ==== Stats written to file stats_0003_msgmaxsize_1926045794783983020.json ====
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:488: rd_unittest: Unittests will not error out on slow CPUs
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: empty tqh[0]
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: prepend 1,0
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: prepend 2,1,0
[0003_msgmaxsize             /  0.000s] Test config file test.conf not found
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: insert 1
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: insert 1,2
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: append 1
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: append 1,2
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: insert 1,0,2
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: insert 2,0,1
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:371: unittest_sysqueue
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: sysqueue: PASS
[0004_conf                   /  0.000s] RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdbuf.c:1265: do_unittest_write_read
================= Running test 0004_conf =================
[0004_conf                   /  0.000s] RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdbuf.c:1426: do_unittest_write_split_seek
==== Stats written to file stats_0004_conf_5728692381310818804.json ====
[0003_msgmaxsize             /  0.001s] Setting test timeout to 10s * 2.7
[0004_conf                   /  0.000s] Test config file test.conf not found
[0004_conf                   /  0.000s] Setting test timeout to 10s * 2.7
[0004_conf                   /  0.000s] Using topic "rdkafkatest_0004"
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdbuf.c:1517: do_unittest_write_read_payload_correctness
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdbuf.c:1582: do_unittest_write_iov
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: rdbuf: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: rdvarint: PASS
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/crc32c.c:413: unittest_crc32c: Calculate CRC32C using hardware (SSE42)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/crc32c.c:424: unittest_crc32c: Calculate CRC32C using software
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/crc32c.c:431: unittest_crc32c
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: crc32c: PASS
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1618: unittest_msgq_order: FIFO: testing in FIFO mode
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1806: unittest_msg_seq_wrap
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: get baseline insert time
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 2 messages into destq with 2 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 2us, 0.5000us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: get baseline insert time
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 2 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 3 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 1.0000us/msg over 2 messages in 2us
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: single-message ranges
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 4 messages into destq with 5 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 4us, 0.4444us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: single-message ranges
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 5 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 6 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 7 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 8 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 1.0000us/msg over 4 messages in 4us
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: many messages
[0004_conf                   /  0.012s] : on_new() called
[0002_unkpart                /  0.014s] Created    kafka instance 0002_unkpart#producer-1
[0002_unkpart                /  0.014s] Using topic "rdkafkatest_0002"
[0001_multiobj               /  0.014s] Created    kafka instance 0001_multiobj#producer-2
[0003_msgmaxsize             /  0.013s] Created    kafka instance 0003_msgmaxsize#producer-3
[0003_msgmaxsize             /  0.013s] Using topic "rdkafkatest_0003"
[0003_msgmaxsize             /  0.013s] Msg #0 produce() returned expected NO_ERROR for value size 5000 and key size -1
%7|1594295216.624|INIT|0004_conf#producer-4| [thrd:app]: librdkafka v1.4.4-devel (0x10404ff) 0004_conf#producer-4 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_gssapi,sasl_plain,sasl_scram,plugins,zstd,sasl_oauthbearer, CMAKE GNU GNU PKGCONFIG HDRHISTOGRAM ZLIB ZSTD LIBDL PLUGINS SSL SASL_SCRAM SASL_OAUTHBEARER SASL_CYRUS LZ4_EXT C11THREADS CRC32C_HW SNAPPY SOCKEM, debug 0x80c)
[0004_conf                   /  0.013s] Created    kafka instance 0004_conf#producer-4
%7|1594295216.624|TOPIC|0004_conf#producer-4| [thrd:app]: New local topic: rdkafkatest_0004
%7|1594295216.624|TOPPARNEW|0004_conf#producer-4| [thrd:app]: NEW rdkafkatest_0004 [-1] 0x7f7f00002740 (at rd_kafka_topic_new0:397)
%7|1594295216.624|METADATA|0004_conf#producer-4| [thrd:app]: Skipping metadata refresh of 1 topic(s): no usable brokers
%7|1594295216.624|DESTROY|0004_conf#producer-4| [thrd:app]: Terminating instance (destroy flags none (0x0))
%7|1594295216.624|DESTROY|0004_conf#producer-4| [thrd:main]: Destroy internal
%7|1594295216.624|DESTROY|0004_conf#producer-4| [thrd:main]: Removing all topics
%7|1594295216.624|TOPPARREMOVE|0004_conf#producer-4| [thrd:main]: Removing toppar rdkafkatest_0004 [-1] 0x7f7f00002740
%7|1594295216.624|DESTROY|0004_conf#producer-4| [thrd:main]: rdkafkatest_0004 [-1]: 0x7f7f00002740 DESTROY_FINAL
[0003_msgmaxsize             /  0.014s] Msg #1 produce() returned expected NO_ERROR for value size 99900 and key size 0
[0003_msgmaxsize             /  0.014s] Msg #2 produce() returned expected MSG_SIZE_TOO_LARGE for value size 100000 and key size 0
[0003_msgmaxsize             /  0.014s] Msg #3 produce() returned expected MSG_SIZE_TOO_LARGE for value size 0 and key size 100000
[0003_msgmaxsize             /  0.014s] Msg #4 produce() returned expected MSG_SIZE_TOO_LARGE for value size 100000 and key size 1000
[0003_msgmaxsize             /  0.014s] Msg #5 produce() returned expected MSG_SIZE_TOO_LARGE for value size 101000 and key size 0
[0003_msgmaxsize             /  0.015s] Msg #6 produce() returned expected NO_ERROR for value size -1 and key size 99000
%7|1594295216.625|INIT|0004_conf#producer-5| [thrd:app]: librdkafka v1.4.4-devel (0x10404ff) 0004_conf#producer-5 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_gssapi,sasl_plain,sasl_scram,plugins,zstd,sasl_oauthbearer, CMAKE GNU GNU PKGCONFIG HDRHISTOGRAM ZLIB ZSTD LIBDL PLUGINS SSL SASL_SCRAM SASL_OAUTHBEARER SASL_CYRUS LZ4_EXT C11THREADS CRC32C_HW SNAPPY SOCKEM, debug 0x80c)
[0004_conf                   /  0.014s] Created    kafka instance 0004_conf#producer-5
%7|1594295216.625|TOPIC|0004_conf#producer-5| [thrd:app]: New local topic: rdkafkatest_0004
%7|1594295216.625|TOPPARNEW|0004_conf#producer-5| [thrd:app]: NEW rdkafkatest_0004 [-1] 0x7f7f00003550 (at rd_kafka_topic_new0:397)
%7|1594295216.625|METADATA|0004_conf#producer-5| [thrd:app]: Skipping metadata refresh of 1 topic(s): no usable brokers
%7|1594295216.625|DESTROY|0004_conf#producer-5| [thrd:app]: Terminating instance (destroy flags none (0x0))
%7|1594295216.625|DESTROY|0004_conf#producer-5| [thrd:main]: Destroy internal
%7|1594295216.625|DESTROY|0004_conf#producer-5| [thrd:main]: Removing all topics
%7|1594295216.625|TOPPARREMOVE|0004_conf#producer-5| [thrd:main]: Removing toppar rdkafkatest_0004 [-1] 0x7f7f00003550
%7|1594295216.626|DESTROY|0004_conf#producer-5| [thrd:main]: rdkafkatest_0004 [-1]: 0x7f7f00003550 DESTROY_FINAL
[0004_conf                   /  0.014s] Incremental S2F tests
[0004_conf                   /  0.015s]   Set: generic,broker,queue,cgrp
[0004_conf                   /  0.015s]   Now: generic,broker,queue,cgrp
[0004_conf                   /  0.015s]   Set: -broker,+queue,topic
[0004_conf                   /  0.015s]   Now: generic,topic,queue,cgrp
[0004_conf                   /  0.015s]   Set: -all,security,-fetch,+metadata
[0004_conf                   /  0.015s]   Now: metadata,security
[0004_conf                   /  0.015s] Error reporting for S2F properties
[0004_conf                   /  0.015s] Ok: Invalid value "invalid-value" for configuration property "debug"
[0004_conf                   /  0.015s] Canonical tests
[0004_conf                   /  0.015s]   Set: request.required.acks=0 expect 0 (topic)
[0004_conf                   /  0.015s]   Set: request.required.acks=-1 expect -1 (topic)
[0004_conf                   /  0.015s]   Set: request.required.acks=1 expect 1 (topic)
[0004_conf                   /  0.015s]   Set: acks=3 expect 3 (topic)
[0004_conf                   /  0.015s]   Set: request.required.acks=393 expect 393 (topic)
[0004_conf                   /  0.015s]   Set: request.required.acks=bad expect (null) (topic)
[0004_conf                   /  0.015s]   Set: request.required.acks=all expect -1 (topic)
[0004_conf                   /  0.015s]   Set: request.required.acks=all expect -1 (global)
[0004_conf                   /  0.015s]   Set: acks=0 expect 0 (topic)
[0004_conf                   /  0.015s]   Set: sasl.mechanisms=GSSAPI expect GSSAPI (global)
[0004_conf                   /  0.015s]   Set: sasl.mechanisms=PLAIN expect PLAIN (global)
[0004_conf                   /  0.015s]   Set: sasl.mechanisms=GSSAPI,PLAIN expect (null) (global)
[0004_conf                   /  0.015s]   Set: sasl.mechanisms= expect (null) (global)
[0004_conf                   /  0.015s]   Set: linger.ms=12555.3 expect 12555.3 (global)
[0004_conf                   /  0.015s]   Set: linger.ms=1500.000 expect 1500 (global)
[0004_conf                   /  0.015s]   Set: linger.ms=0.0001 expect 0.0001 (global)
[0004_conf                   /  0.017s] Ok: `acks` must be set to `all` when `enable.idempotence` is true
[0004_conf                   /  0.017s] Ok: Java TrustStores are not supported, use `ssl.ca.location` and a certificate file instead. See https://github.com/edenhill/librdkafka/wiki/Using-SSL-with-librdkafka for more information.
[0004_conf                   /  0.017s] Ok: Java JAAS configuration is not supported, see https://github.com/edenhill/librdkafka/wiki/Using-SASL-with-librdkafka for more information.
[0004_conf                   /  0.017s] Ok: Internal property "interceptors" not settable
%3|1594295216.629|TOPICCONF|rdkafka#producer-9| [thrd:app]: Incompatible configuration settings for topic "mytopic": `acks` must be set to `all` when `enable.idempotence` is true
%3|1594295216.631|TOPICCONF|rdkafka#producer-12| [thrd:app]: Incompatible configuration settings for topic "mytopic": `queuing.strategy` must be set to `fifo` when `enable.idempotence` is true
[0004_conf                   /  0.020s] Instance config linger.ms=123
[0004_conf                   /  0.021s] Instance config group.id=test1
[0004_conf                   /  0.021s] Instance config enable.auto.commit=false
[0004_conf                   /  0.021s] 0004_conf: duration 21.151ms
[0004_conf                   /  0.021s] ================= Test 0004_conf PASSED =================
[<MAIN>                      /  0.124s] Too many tests running (5 >= 5): postponing 0006_symbols start...
[0005_order                  /  0.000s] ================= Running test 0005_order =================
[0005_order                  /  0.000s] ==== Stats written to file stats_0005_order_6571881841242453216.json ====
[0005_order                  /  0.000s] Test config file test.conf not found
[0005_order                  /  0.000s] Setting test timeout to 10s * 2.7
[0005_order                  /  0.000s] Created    kafka instance 0005_order#producer-14
[0005_order                  /  0.001s] Using topic "rdkafkatest_0005"
[0005_order                  /  0.053s] PRODUCE: duration 52.274ms
[0005_order                  /  0.053s] Produced 50000 messages, waiting for deliveries
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 4315956 messages into destq with 165288 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 2005863us, 0.4476us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: many messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 100001 messages into destq with 165288 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 17599us, 0.1760us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 50001 messages into destq with 265289 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 20983us, 0.4197us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 20001 messages into destq with 315290 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 31445us, 1.5722us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 59129 messages into destq with 335291 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 27819us, 0.4705us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 86823 messages into destq with 394420 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 38430us, 0.4426us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 4000001 messages into destq with 481243 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 328680us, 0.0822us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 0.1077us/msg over 4315956 messages in 464956us
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: issue #2508
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 145952 messages into destq with 154875 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 45739us, 0.1520us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: issue #2508
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 59129 messages into destq with 154875 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 13221us, 0.2236us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 86823 messages into destq with 214004 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 14127us, 0.1627us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 0.1874us/msg over 145952 messages in 27348us
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: issue #2450 (v1.2.1 regression)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 86 messages into destq with 199999 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 8891us, 0.0444us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: issue #2450 (v1.2.1 regression)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 199999 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 8885us, 4442.5000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 5 messages into destq with 200001 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 8926us, 1785.2000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 4 messages into destq with 200006 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 8889us, 2222.2500us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 200010 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 8917us, 4458.5000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 3 messages into destq with 200012 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9000us, 3000.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 61 messages into destq with 200015 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9013us, 147.7541us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 200076 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 8916us, 4458.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 200078 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 8938us, 4469.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 200080 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9136us, 4568.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 3 messages into destq with 200082 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9129us, 3043.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 1043.5930us/msg over 86 messages in 89749us
RDUT: WARN: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2025: unittest_msgq_insert_each_sort: maximum us/msg exceeded: 1043.5930 > 3.0000 us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: msg: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdmurmur2.c:158: unittest_murmur2
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: murmurhash: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdfnv1a.c:111: unittest_fnv1a
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: fnv1a: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:468: ut_high_sigfig
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:500: ut_quantile
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:519: ut_mean
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:541: ut_stddev
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:560: ut_totalcount
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:579: ut_max
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:597: ut_min
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:617: ut_reset
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:631: ut_nan
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:646: ut_sigfigs
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:662: ut_minmax_trackable
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:672: ut_unitmagnitude_overflow
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:705: ut_subbucketmask_overflow
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: rdhdrhistogram: PASS
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_conf.c:3920: unittest_conf: Safified client.software.name="aba.-va"
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_conf.c:3928: unittest_conf: Safified client.software.version="1.2.3.4.5----a"
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_conf.c:3932: unittest_conf
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: conf: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_broker.c:1849: rd_ut_reconnect_backoff
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: broker: PASS
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4196: unittest_idempotent_producer: Verifying idempotent producer error handling
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4369: unittest_idempotent_producer: Got DeliveryReport event with 3 message(s)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4369: unittest_idempotent_producer: Got DeliveryReport event with 3 message(s)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4369: unittest_idempotent_producer: Got DeliveryReport event with 3 message(s)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4369: unittest_idempotent_producer: Got DeliveryReport event with 3 message(s)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4398: unittest_idempotent_producer
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: request: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1559: do_unittest_config_no_principal_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1587: do_unittest_config_empty_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1659: do_unittest_config_empty_value_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1701: do_unittest_config_value_with_quote_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1616: do_unittest_config_unrecognized_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1445: do_unittest_config_defaults
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1487: do_unittest_config_explicit_scope_and_life
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1530: do_unittest_config_all_explicit_values
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1740: do_unittest_config_extensions
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1764: do_unittest_illegal_extension_keys_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1796: do_unittest_odd_extension_size_should_fail
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: sasl_oauthbearer: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msgset_reader.c:1713: unittest_aborted_txns
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: aborted_txns: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_cgrp.c:3794: unittest_consumer_group_metadata
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: cgrp: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_scram.c:943: unittest_scram_nonce
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_scram.c:983: unittest_scram_safe
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: scram: PASS
[0000_unittests              /  8.554s] 0000_unittests: duration 8554.132ms
[0000_unittests              /  8.554s] ================= Test 0000_unittests PASSED =================
[<MAIN>                      /  8.656s] Too many tests running (5 >= 5): postponing 0007_autotopic start...
[0006_symbols                /  0.000s] ================= Running test 0006_symbols =================
[0006_symbols                /  0.000s] ==== Stats written to file stats_0006_symbols_1876803674096874915.json ====
[0006_symbols                /  0.000s] 0006_symbols: duration 0.000ms
[0006_symbols                /  0.000s] ================= Test 0006_symbols PASSED =================
[<MAIN>                      /  8.757s] Too many tests running (5 >= 5): postponing 0008_reqacks start...
[0007_autotopic              /  0.000s] ================= Running test 0007_autotopic =================
[0007_autotopic              /  0.000s] ==== Stats written to file stats_0007_autotopic_5178964978228119424.json ====
[0007_autotopic              /  0.000s] Test config file test.conf not found
[0007_autotopic              /  0.000s] Setting test timeout to 10s * 2.7
[0007_autotopic              /  0.000s] NOTE! This test requires auto.create.topics.enable=true to be configured on the broker!
[0007_autotopic              /  0.000s] Created    kafka instance 0007_autotopic#producer-16
[0007_autotopic              /  0.001s] Using topic "rdkafkatest_rnd20e5c6b8749ff65e_0007_autotopic"
[<MAIN>                      / 18.773s] Too many tests running (5 >= 5): postponing 0008_reqacks start...
TEST 20200709124722 (bare, scenario default) SUMMARY
#==================================================================#
| <MAIN>                                   |     PASSED |  26.085s |
| 0000_unittests                           |     PASSED |   8.554s |
| 0001_multiobj                            |    RUNNING |  26.084s |
| 0002_unkpart                             |     FAILED |  26.084s |
| 0003_msgmaxsize                          |    RUNNING |  26.083s |
| 0004_conf                                |     PASSED |   0.021s |
| 0005_order                               |    RUNNING |  25.960s |
| 0006_symbols                             |     PASSED |   0.000s |
| 0007_autotopic                           |    RUNNING |  17.327s |
| 0008_reqacks                             |        DNS |   0.000s |
| 0009_mock_cluster                        |        DNS |   0.000s |
| 0011_produce_batch                       |        DNS |   0.000s |
| 0012_produce_consume                     |        DNS |   0.000s |
| 0013_null_msgs                           |        DNS |   0.000s |
| 0014_reconsume_191                       |        DNS |   0.000s |
| 0015_offsets_seek                        |        DNS |   0.000s |
| 0016_client_swname                       |        DNS |   0.000s |
| 0017_compression                         |        DNS |   0.000s |
| 0018_cgrp_term                           |        DNS |   0.000s |
| 0019_list_groups                         |        DNS |   0.000s |
| 0020_destroy_hang                        |        DNS |   0.000s |
| 0021_rkt_destroy                         |        DNS |   0.000s |
| 0022_consume_batch                       |        DNS |   0.000s |
| 0025_timers                              |        DNS |   0.000s |
| 0026_consume_pause                       |        DNS |   0.000s | Fragile test due to #2190
| 0028_long_topicnames                     |        DNS |   0.000s | https://github.com/edenhill/librdkafka/issues/529
| 0029_assign_offset                       |        DNS |   0.000s |
| 0030_offset_commit                       |        DNS |   0.000s |
| 0031_get_offsets                         |        DNS |   0.000s |
| 0033_regex_subscribe                     |        DNS |   0.000s |
| 0033_regex_subscribe_local               |        DNS |   0.000s |
| 0034_offset_reset                        |        DNS |   0.000s |
| 0035_api_version                         |        DNS |   0.000s |
| 0036_partial_fetch                       |        DNS |   0.000s |
| 0037_destroy_hang_local                  |        DNS |   0.000s |
| 0038_performance                         |        DNS |   0.000s |
| 0039_event_dr                            |        DNS |   0.000s |
| 0039_event                               |        DNS |   0.000s |
| 0040_io_event                            |        DNS |   0.000s |
| 0041_fetch_max_bytes                     |        DNS |   0.000s |
| 0042_many_topics                         |        DNS |   0.000s |
| 0043_no_connection                       |        DNS |   0.000s |
| 0044_partition_cnt                       |        DNS |   0.000s |
| 0045_subscribe_update                    |        DNS |   0.000s |
| 0045_subscribe_update_topic_remove       |        DNS |   0.000s |
| 0045_subscribe_update_non_exist_and_partchange |        DNS |   0.000s |
| 0046_rkt_cache                           |        DNS |   0.000s |
| 0047_partial_buf_tmout                   |        DNS |   0.000s |
| 0048_partitioner                         |        DNS |   0.000s |
| 0049_consume_conn_close                  |        DNS |   0.000s |
| 0050_subscribe_adds                      |        DNS |   0.000s |
| 0051_assign_adds                         |        DNS |   0.000s |
| 0052_msg_timestamps                      |        DNS |   0.000s |
| 0053_stats_timing                        |        DNS |   0.000s |
| 0053_stats                               |        DNS |   0.000s |
| 0054_offset_time                         |        DNS |   0.000s |
| 0055_producer_latency                    |        DNS |   0.000s |
| 0056_balanced_group_mt                   |        DNS |   0.000s |
| 0057_invalid_topic                       |        DNS |   0.000s |
| 0058_log                                 |        DNS |   0.000s |
| 0059_bsearch                             |        DNS |   0.000s |
| 0060_op_prio                             |        DNS |   0.000s |
| 0061_consumer_lag                        |        DNS |   0.000s |
| 0062_stats_event                         |        DNS |   0.000s |
| 0063_clusterid                           |        DNS |   0.000s |
| 0064_interceptors                        |        DNS |   0.000s |
| 0065_yield                               |        DNS |   0.000s |
| 0066_plugins                             |        DNS |   0.000s | dynamic loading of tests might not be fixed for this platform
| 0067_empty_topic                         |        DNS |   0.000s |
| 0068_produce_timeout                     |        DNS |   0.000s |
| 0069_consumer_add_parts                  |        DNS |   0.000s |
| 0070_null_empty                          |        DNS |   0.000s |
| 0072_headers_ut                          |        DNS |   0.000s |
| 0073_headers                             |        DNS |   0.000s |
| 0074_producev                            |        DNS |   0.000s |
| 0075_retry                               |        DNS |   0.000s |
| 0076_produce_retry                       |        DNS |   0.000s |
| 0077_compaction                          |        DNS |   0.000s |
| 0078_c_from_cpp                          |        DNS |   0.000s |
| 0079_fork                                |        DNS |   0.000s | using a fork():ed rd_kafka_t is not supported and will most likely hang
| 0080_admin_ut                            |        DNS |   0.000s |
| 0081_admin                               |        DNS |   0.000s |
| 0082_fetch_max_bytes                     |        DNS |   0.000s |
| 0083_cb_event                            |        DNS |   0.000s |
| 0084_destroy_flags_local                 |        DNS |   0.000s |
| 0084_destroy_flags                       |        DNS |   0.000s |
| 0085_headers                             |        DNS |   0.000s |
| 0086_purge_local                         |        DNS |   0.000s |
| 0086_purge_remote                        |        DNS |   0.000s |
| 0088_produce_metadata_timeout            |        DNS |   0.000s |
| 0089_max_poll_interval                   |        DNS |   0.000s |
| 0090_idempotence                         |        DNS |   0.000s |
| 0091_max_poll_interval_timeout           |        DNS |   0.000s |
| 0092_mixed_msgver                        |        DNS |   0.000s |
| 0093_holb_consumer                       |        DNS |   0.000s |
| 0094_idempotence_msg_timeout             |        DNS |   0.000s |
| 0095_all_brokers_down                    |        DNS |   0.000s |
| 0097_ssl_verify                          |        DNS |   0.000s |
| 0098_consumer_txn                        |        DNS |   0.000s |
| 0099_commit_metadata                     |        DNS |   0.000s |
| 0100_thread_interceptors             [0002_unkpart                / 26.085s] # Test report written to test_report_20200709124722.json
[0002_unkpart                / 26.085s] TEST FAILURE
### Test "0002_unkpart" failed at /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/tests/test.c:1092:check_test_timeouts() at Thu Jul  9 12:47:22 2020: ###
Test 0002_unkpart timed out (timeout set to 26 seconds)
<end of output>
Test time =  26.15 sec
----------------------------------------------------------
Test Failed.
"RdKafkaTestInParallel" end time: Jul 09 12:47 BST
"RdKafkaTestInParallel" time elapsed: 00:00:26
----------------------------------------------------------

2/3 Testing: RdKafkaTestSequentially
2/3 Test: RdKafkaTestSequentially
Command: "/home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/x86_64-redhat-linux-gnu/tests/test-runner" "-p1"
Directory: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/x86_64-redhat-linux-gnu/tests
"RdKafkaTestSequentially" start time: Jul 09 12:47 BST
Output:
----------------------------------------------------------
[<MAIN>                      /  0.000s] Test config file test.conf not found
[<MAIN>                      /  0.000s] Setting test timeout to 10s * 1.0
[<MAIN>                      /  0.000s] Git version: HEAD
[<MAIN>                      /  0.000s] Broker version: 2.4.0.0 (2.4.0.0)
[<MAIN>                      /  0.000s] Tests to run : all
[<MAIN>                      /  0.000s] Test mode    : bare
[<MAIN>                      /  0.000s] Test scenario: default
[<MAIN>                      /  0.000s] Test filter  : no filter
[<MAIN>                      /  0.000s] Test timeout multiplier: 1.0
[<MAIN>                      /  0.000s] Action on test failure: continue other tests
[<MAIN>                      /  0.000s] Current directory: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/x86_64-redhat-linux-gnu/tests
[<MAIN>                      /  0.000s] Setting test timeout to 30s * 1.0
[<MAIN>                      /  0.000s] Too many tests running (1 >= 1): postponing 0001_multiobj start...
[0000_unittests              /  0.000s] ================= Running test 0000_unittests =================
[0000_unittests              /  0.000s] ==== Stats written to file stats_0000_unittests_4823930869304952267.json ====
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:488: rd_unittest: Unittests will not error out on slow CPUs
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: empty tqh[0]
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: prepend 1,0
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: prepend 2,1,0
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: insert 1
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: insert 1,2
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: append 1
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: append 1,2
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: insert 1,0,2
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: insert 2,0,1
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:371: unittest_sysqueue
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: sysqueue: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdbuf.c:1265: do_unittest_write_read
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdbuf.c:1426: do_unittest_write_split_seek
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdbuf.c:1517: do_unittest_write_read_payload_correctness
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdbuf.c:1582: do_unittest_write_iov
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: rdbuf: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: rdvarint: PASS
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/crc32c.c:413: unittest_crc32c: Calculate CRC32C using hardware (SSE42)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/crc32c.c:424: unittest_crc32c: Calculate CRC32C using software
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/crc32c.c:431: unittest_crc32c
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: crc32c: PASS
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1618: unittest_msgq_order: FIFO: testing in FIFO mode
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1806: unittest_msg_seq_wrap
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: get baseline insert time
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 2 messages into destq with 2 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 2us, 0.5000us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: get baseline insert time
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 2 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 3 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 0us, 0.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 0.5000us/msg over 2 messages in 1us
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: single-message ranges
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 4 messages into destq with 5 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 4us, 0.4444us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: single-message ranges
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 5 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 6 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 7 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 8 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 1.0000us/msg over 4 messages in 4us
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: many messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 4315956 messages into destq with 165288 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 2023872us, 0.4516us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: many messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 100001 messages into destq with 165288 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 17595us, 0.1759us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 50001 messages into destq with 265289 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 21084us, 0.4217us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 20001 messages into destq with 315290 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 23044us, 1.1521us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 59129 messages into destq with 335291 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 28309us, 0.4788us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 86823 messages into destq with 394420 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 38974us, 0.4489us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 4000001 messages into destq with 481243 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 394750us, 0.0987us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 0.1214us/msg over 4315956 messages in 523756us
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: issue #2508
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 145952 messages into destq with 154875 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 50211us, 0.1669us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: issue #2508
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 59129 messages into destq with 154875 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 15315us, 0.2590us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 86823 messages into destq with 214004 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 16943us, 0.1951us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 0.2210us/msg over 145952 messages in 32258us
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: issue #2450 (v1.2.1 regression)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 86 messages into destq with 199999 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 10690us, 0.0534us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: issue #2450 (v1.2.1 regression)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 199999 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 10136us, 5068.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 5 messages into destq with 200001 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9828us, 1965.6000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 4 messages into destq with 200006 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9640us, 2410.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 200010 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9614us, 4807.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 3 messages into destq with 200012 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9591us, 3197.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 61 messages into destq with 200015 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9519us, 156.0492us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 200076 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9639us, 4819.5000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 200078 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9553us, 4776.5000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 200080 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9479us, 4739.5000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 3 messages into destq with 200082 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9494us, 3164.6667us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 1122.0116us/msg over 86 messages in 96493us
RDUT: WARN: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2025: unittest_msgq_insert_each_sort: maximum us/msg exceeded: 1122.0116 > 1.5000 us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: msg: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdmurmur2.c:158: unittest_murmur2
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: murmurhash: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdfnv1a.c:111: unittest_fnv1a
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: fnv1a: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:468: ut_high_sigfig
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:500: ut_quantile
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:519: ut_mean
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:541: ut_stddev
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:560: ut_totalcount
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:579: ut_max
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:597: ut_min
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:617: ut_reset
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:631: ut_nan
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:646: ut_sigfigs
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:662: ut_minmax_trackable
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:672: ut_unitmagnitude_overflow
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:705: ut_subbucketmask_overflow
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: rdhdrhistogram: PASS
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_conf.c:3920: unittest_conf: Safified client.software.name="aba.-va"
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_conf.c:3928: unittest_conf: Safified client.software.version="1.2.3.4.5----a"
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_conf.c:3932: unittest_conf
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: conf: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_broker.c:1849: rd_ut_reconnect_backoff
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: broker: PASS
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4196: unittest_idempotent_producer: Verifying idempotent producer error handling
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4369: unittest_idempotent_producer: Got DeliveryReport event with 3 message(s)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4369: unittest_idempotent_producer: Got DeliveryReport event with 3 message(s)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4369: unittest_idempotent_producer: Got DeliveryReport event with 3 message(s)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4369: unittest_idempotent_producer: Got DeliveryReport event with 3 message(s)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4398: unittest_idempotent_producer
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: request: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1559: do_unittest_config_no_principal_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1587: do_unittest_config_empty_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1659: do_unittest_config_empty_value_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1701: do_unittest_config_value_with_quote_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1616: do_unittest_config_unrecognized_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1445: do_unittest_config_defaults
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1487: do_unittest_config_explicit_scope_and_life
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1530: do_unittest_config_all_explicit_values
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1740: do_unittest_config_extensions
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1764: do_unittest_illegal_extension_keys_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1796: do_unittest_odd_extension_size_should_fail
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: sasl_oauthbearer: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msgset_reader.c:1713: unittest_aborted_txns
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: aborted_txns: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_cgrp.c:3794: unittest_consumer_group_metadata
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: cgrp: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_scram.c:943: unittest_scram_nonce
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_scram.c:983: unittest_scram_safe
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: scram: PASS
[0000_unittests              /  8.579s] 0000_unittests: duration 8579.287ms
[0000_unittests              /  8.579s] ================= Test 0000_unittests PASSED =================
[<MAIN>                      /  8.681s] Too many tests running (1 >= 1): postponing 0002_unkpart start...
[0001_multiobj               /  0.000s] ================= Running test 0001_multiobj =================
[0001_multiobj               /  0.000s] ==== Stats written to file stats_0001_multiobj_749846938525037737.json ====
[0001_multiobj               /  0.000s] Creating and destroying 5 kafka instances
[0001_multiobj               /  0.000s] Test config file test.conf not found
[0001_multiobj               /  0.000s] Setting test timeout to 30s * 1.0
[0001_multiobj               /  0.000s] Using topic "rdkafkatest_0001"
[0001_multiobj               /  0.001s] Created    kafka instance 0001_multiobj#producer-2
[<MAIN>                      / 18.695s] Too many tests running (1 >= 1): postponing 0002_unkpart start...
[<MAIN>                      / 28.711s] Too many tests running (1 >= 1): postponing 0002_unkpart start...
TEST 20200709124801 (bare, scenario default) SUMMARY
#==================================================================#
| <MAIN>                                   |     PASSED |  38.730s |
| 0000_unittests                           |     PASSED |   8.579s |
| 0001_multiobj                            |     FAILED |  30.049s |
| 0002_unkpart                             |        DNS |   0.000s |
| 0003_msgmaxsize                          |        DNS |   0.000s |
| 0004_conf                                |        DNS |   0.000s |
| 0005_order                               |        DNS |   0.000s |
| 0006_symbols                             |        DNS |   0.000s |
| 0007_autotopic                           |        DNS |   0.000s |
| 0008_reqacks                             |        DNS |   0.000s |
| 0009_mock_cluster                        |        DNS |   0.000s |
| 0011_produce_batch                       |        DNS |   0.000s |
| 0012_produce_consume                     |        DNS |   0.000s |
| 0013_null_msgs                           |        DNS |   0.000s |
| 0014_reconsume_191                       |        DNS |   0.000s |
| 0015_offsets_seek                        |        DNS |   0.000s |
| 0016_client_swname                       |        DNS |   0.000s |
| 0017_compression                         |        DNS |   0.000s |
| 0018_cgrp_term                           |        DNS |   0.000s |
| 0019_list_groups                         |        DNS |   0.000s |
| 0020_destroy_hang                        |        DNS |   0.000s |
| 0021_rkt_destroy                         |        DNS |   0.000s |
| 0022_consume_batch                       |        DNS |   0.000s |
| 0025_timers                              |        DNS |   0.000s |
| 0026_consume_pause                       |        DNS |   0.000s | Fragile test due to #2190
| 0028_long_topicnames                     |        DNS |   0.000s | https://github.com/edenhill/librdkafka/issues/529
| 0029_assign_offset                       |        DNS |   0.000s |
| 0030_offset_commit                       |        DNS |   0.000s |
| 0031_get_offsets                         |        DNS |   0.000s |
| 0033_regex_subscribe                     |        DNS |   0.000s |
| 0033_regex_subscribe_local               |        DNS |   0.000s |
| 0034_offset_reset                        |        DNS |   0.000s |
| 0035_api_version                         |        DNS |   0.000s |
| 0036_partial_fetch                       |        DNS |   0.000s |
| 0037_destroy_hang_local                  |        DNS |   0.000s |
| 0038_performance                         |        DNS |   0.000s |
| 0039_event_dr                            |        DNS |   0.000s |
| 0039_event                               |        DNS |   0.000s |
| 0040_io_event                            |        DNS |   0.000s |
| 0041_fetch_max_bytes                     |        DNS |   0.000s |
| 0042_many_topics                         |        DNS |   0.000s |
| 0043_no_connection                       |        DNS |   0.000s |
| 0044_partition_cnt                       |        DNS |   0.000s |
| 0045_subscribe_update                    |        DNS |   0.000s |
| 0045_subscribe_update_topic_remove       |        DNS |   0.000s |
| 0045_subscribe_update_non_exist_and_partchange |        DNS |   0.000s |
| 0046_rkt_cache                           |        DNS |   0.000s |
| 0047_partial_buf_tmout                   |        DNS |   0.000s |
| 0048_partitioner                         |        DNS |   0.000s |
| 0049_consume_conn_close                  |        DNS |   0.000s |
| 0050_subscribe_adds                      |        DNS |   0.000s |
| 0051_assign_adds                         |        DNS |   0.000s |
| 0052_msg_timestamps                      |        DNS |   0.000s |
| 0053_stats_timing                        |        DNS |   0.000s |
| 0053_stats                               |        DNS |   0.000s |
| 0054_offset_time                         |        DNS |   0.000s |
| 0055_producer_latency                    |        DNS |   0.000s |
| 0056_balanced_group_mt                   |        DNS |   0.000s |
| 0057_invalid_topic                       |        DNS |   0.000s |
| 0058_log                                 |        DNS |   0.000s |
| 0059_bsearch                             |        DNS |   0.000s |
| 0060_op_prio                             |        DNS |   0.000s |
| 0061_consumer_lag                        |        DNS |   0.000s |
| 0062_stats_event                         |        DNS |   0.000s |
| 0063_clusterid                           |        DNS |   0.000s |
| 0064_interceptors                        |        DNS |   0.000s |
| 0065_yield                               |        DNS |   0.000s |
| 0066_plugins                             |        DNS |   0.000s | dynamic loading of tests might not be fixed for this platform
| 0067_empty_topic                         |        DNS |   0.000s |
| 0068_produce_timeout                     |        DNS |   0.000s |
| 0069_consumer_add_parts                  |        DNS |   0.000s |
| 0070_null_empty                          |        DNS |   0.000s |
| 0072_headers_ut                          |        DNS |   0.000s |
| 0073_headers                             |        DNS |   0.000s |
| 0074_producev                            |        DNS |   0.000s |
| 0075_retry                               |        DNS |   0.000s |
| 0076_produce_retry                       |        DNS |   0.000s |
| 0077_compaction                          |        DNS |   0.000s |
| 0078_c_from_cpp                          |        DNS |   0.000s |
| 0079_fork                                |        DNS |   0.000s | using a fork():ed rd_kafka_t is not supported and will most likely hang
| 0080_admin_ut                            |        DNS |   0.000s |
| 0081_admin                               |        DNS |   0.000s |
| 0082_fetch_max_bytes                     |        DNS |   0.000s |
| 0083_cb_event                            |        DNS |   0.000s |
| 0084_destroy_flags_local                 |        DNS |   0.000s |
| 0084_destroy_flags                       |        DNS |   0.000s |
| 0085_headers                             |        DNS |   0.000s |
| 0086_purge_local                         |        DNS |   0.000s |
| 0086_purge_remote                        |        DNS |   0.000s |
| 0088_produce_metadata_timeout            |        DNS |   0.000s |
| 0089_max_poll_interval                   |        DNS |   0.000s |
| 0090_idempotence                         |        DNS |   0.000s |
| 0091_max_poll_interval_timeout           |        DNS |   0.000s |
| 0092_mixed_msgver                        |        DNS |   0.000s |
| 0093_holb_consumer                       |        DNS |   0.000s |
| 0094_idempotence_msg_timeout             |        DNS |   0.000s |
| 0095_all_brokers_down                    |        DNS |   0.000s |
| 0097_ssl_verify                          |        DNS |   0.000s |
| 0098_consumer_txn                        |        DNS |   0.000s |
| 0099_commit_metadata                     |        DNS |   0.000s |
| 0100_thread_interceptors             [0001_multiobj               / 30.050s] # Test report written to test_report_20200709124801.json
[0001_multiobj               / 30.050s] TEST FAILURE
### Test "0001_multiobj" failed at /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/tests/test.c:1092:check_test_timeouts() at Thu Jul  9 12:48:01 2020: ###
Test 0001_multiobj timed out (timeout set to 30 seconds)
<end of output>
Test time =  38.88 sec
----------------------------------------------------------
Test Failed.
"RdKafkaTestSequentially" end time: Jul 09 12:48 BST
"RdKafkaTestSequentially" time elapsed: 00:00:38
----------------------------------------------------------

3/3 Testing: RdKafkaTestBrokerLess
3/3 Test: RdKafkaTestBrokerLess
Command: "/home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/x86_64-redhat-linux-gnu/tests/test-runner" "-p5" "-l"
Directory: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/x86_64-redhat-linux-gnu/tests
"RdKafkaTestBrokerLess" start time: Jul 09 12:48 BST
Output:
----------------------------------------------------------
[<MAIN>                      /  0.000s] Test config file test.conf not found
[<MAIN>                      /  0.000s] Setting test timeout to 10s * 1.0
[<MAIN>                      /  0.000s] Git version: HEAD
[<MAIN>                      /  0.000s] Broker version: 2.4.0.0 (2.4.0.0)
[<MAIN>                      /  0.000s] Tests to run : all
[<MAIN>                      /  0.000s] Test mode    : bare
[<MAIN>                      /  0.000s] Test scenario: default
[<MAIN>                      /  0.000s] Test filter  : local tests only
[<MAIN>                      /  0.000s] Test timeout multiplier: 2.7
[<MAIN>                      /  0.000s] Action on test failure: continue other tests
[<MAIN>                      /  0.000s] Current directory: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/x86_64-redhat-linux-gnu/tests
[<MAIN>                      /  0.000s] Setting test timeout to 30s * 2.7
[0000_unittests              /  0.000s] ================= Running test 0000_unittests =================
[0000_unittests              /  0.000s] ==== Stats written to file stats_0000_unittests_3058531660400538615.json ====
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:488: rd_unittest: [<MAIN>                      /  0.001s] Too many tests running (5 >= 5): postponing 0033_regex_subscribe_local start...
Unittests will not error out on slow CPUs
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: empty tqh[0]
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: prepend 1,0
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: prepend 2,1,0
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: insert 1
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: insert 1,2
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: append 1
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: append 1,2
[0004_conf                   /  0.000s] ================= Running test 0004_conf =================
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: insert 1,0,2[0004_conf                   /  0.000s] [0006_symbols                /  0.000s] ================= Running test 0006_symbols =================

[0006_symbols                /  0.000s] ==== Stats written to file stats_0006_symbols_7060918445285090094.json ====
==== Stats written to file stats_0004_conf_3295678271145451043.json ====
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:155: ut_tq_test: Testing TAILQ: insert 2,0,1
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:371: unittest_sysqueue
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: sysqueue: PASS
[0006_symbols                /  0.000s] [0009_mock_cluster           /  0.000s] RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdbuf.c:1265: do_unittest_write_read
================= Running test 0009_mock_cluster =================
[0009_mock_cluster           /  0.000s] ==== Stats written to file stats_0009_mock_cluster_5558566887339272423.json ====
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdbuf.c:1426: do_unittest_write_split_seek
0006_symbols: duration 0.000ms
[0004_conf                   /  0.000s] Test config file test.conf not found
[0006_symbols                /  0.000s] ================= Test 0006_symbols PASSED =================
[0009_mock_cluster           /  0.000s] [0004_conf                   /  0.000s] Setting test timeout to 10s * 2.7
Using topic "rdkafkatest_rnd4530a0fe0b07fa81_0009_mock_cluster"
[0004_conf                   /  0.000s] Using topic "rdkafkatest_0004"
[0025_timers                 /  0.000s] ================= Running test 0025_timers =================
[0025_timers                 /  0.000s] ==== Stats written to file stats_0025_timers_2551467280748457274.json ====
[0025_timers                 /  0.000s] Test config file test.conf not found
[0025_timers                 /  0.000s] Setting test timeout to 200s * 2.7
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdbuf.c:1517: do_unittest_write_read_payload_correctness
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdbuf.c:1582: do_unittest_write_iov
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: rdbuf: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdvarint.c:103: do_test_rd_uvarint_enc_i64
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: rdvarint: PASS
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/crc32c.c:413: unittest_crc32c: Calculate CRC32C using hardware (SSE42)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/crc32c.c:424: unittest_crc32c: Calculate CRC32C using software
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/crc32c.c:431: unittest_crc32c
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: crc32c: PASS
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1618: unittest_msgq_order: FIFO: testing in FIFO mode
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1806: unittest_msg_seq_wrap
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: get baseline insert time
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 2 messages into destq with 2 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 2us, 0.5000us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: get baseline insert time
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 2 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 3 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 0us, 0.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 0.5000us/msg over 2 messages in 1us
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: single-message ranges
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 4 messages into destq with 5 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 4us, 0.4444us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: single-message ranges
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 5 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 6 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 7 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 1us, 1.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 1 messages into destq with 8 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 0us, 0.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 0.7500us/msg over 4 messages in 3us
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: many messages
[0004_conf                   /  0.013s] : on_new() called
%7|1594295281.660|INIT|0004_conf#producer-3| [thrd:app]: librdkafka v1.4.4-devel (0x10404ff) 0004_conf#producer-3 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_gssapi,sasl_plain,sasl_scram,plugins,zstd,sasl_oauthbearer, CMAKE GNU GNU PKGCONFIG HDRHISTOGRAM ZLIB ZSTD LIBDL PLUGINS SSL SASL_SCRAM SASL_OAUTHBEARER SASL_CYRUS LZ4_EXT C11THREADS CRC32C_HW SNAPPY SOCKEM, debug 0x80c)
[0004_conf                   /  0.014s] Created    kafka instance 0004_conf#producer-3
%7|1594295281.660|TOPIC|0004_conf#producer-3| [thrd:app]: New local topic: rdkafkatest_0004
%7|1594295281.660|TOPPARNEW|0004_conf#producer-3| [thrd:app]: NEW rdkafkatest_0004 [-1] 0x7f4c10002740 (at rd_kafka_topic_new0:397)
[0025_timers                 /  0.014s] Created    kafka instance 0025_timers#consumer-2
[0025_timers                 /  0.014s] %7|1594295281.660|METADATA|0004_conf#producer-3| [thrd:app]: Skipping metadata refresh of 1 topic(s): no usable brokers
rd_kafka_new(): duration 13.608ms
[0025_timers                 /  0.014s] Starting wait loop for 10 expected stats_cb calls with an interval of 600ms
%7|1594295281.660|DESTROY|0004_conf#producer-3| [thrd:app]: Terminating instance (destroy flags none (0x0))
[0009_mock_cluster           /  0.015s] Test config file test.conf not found
[0009_mock_cluster           /  0.015s] Setting test timeout to 30s * 2.7
%7|1594295281.661|DESTROY|0004_conf#producer-3| [thrd:main]: Destroy internal
%7|1594295281.661|DESTROY|0004_conf#producer-3| [thrd:main]: Removing all topics
%7|1594295281.661|TOPPARREMOVE|0004_conf#producer-3| [thrd:main]: Removing toppar rdkafkatest_0004 [-1] 0x7f4c10002740
%7|1594295281.661|DESTROY|0004_conf#producer-3| [thrd:main]: rdkafkatest_0004 [-1]: 0x7f4c10002740 DESTROY_FINAL
[0009_mock_cluster           /  0.015s] Created    kafka instance 0009_mock_cluster#producer-4
%7|1594295281.662|INIT|0004_conf#producer-6| [thrd:app]: librdkafka v1.4.4-devel (0x10404ff) 0004_conf#producer-6 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_gssapi,sasl_plain,sasl_scram,plugins,zstd,sasl_oauthbearer, CMAKE GNU GNU PKGCONFIG HDRHISTOGRAM ZLIB ZSTD LIBDL PLUGINS SSL SASL_SCRAM SASL_OAUTHBEARER SASL_CYRUS LZ4_EXT C11THREADS CRC32C_HW SNAPPY SOCKEM, debug 0x80c)
[0004_conf                   /  0.016s] Created    kafka instance 0004_conf#producer-6
%7|1594295281.662|TOPIC|0004_conf#producer-6| [thrd:app]: New local topic: rdkafkatest_0004
%7|1594295281.662|TOPPARNEW|0004_conf#producer-6| [thrd:app]: NEW rdkafkatest_0004 [-1] 0x7f4c10003550 (at rd_kafka_topic_new0:397)
%7|1594295281.662|METADATA|0004_conf#producer-6| [thrd:app]: Skipping metadata refresh of 1 topic(s): no usable brokers
%7|1594295281.662|DESTROY|0004_conf#producer-6| [thrd:app]: Terminating instance (destroy flags none (0x0))
%7|1594295281.662|DESTROY|0004_conf#producer-6| [thrd:main]: Destroy internal
%7|1594295281.662|DESTROY|0004_conf#producer-6| [thrd:main]: Removing all topics
%7|1594295281.662|TOPPARREMOVE|0004_conf#producer-6| [thrd:main]: Removing toppar rdkafkatest_0004 [-1] 0x7f4c10003550
%7|1594295281.662|DESTROY|0004_conf#producer-6| [thrd:main]: rdkafkatest_0004 [-1]: 0x7f4c10003550 DESTROY_FINAL
[0009_mock_cluster           /  0.016s] Created    kafka instance 0009_mock_cluster#consumer-5
[0009_mock_cluster           /  0.016s] Test config file test.conf not found
[0009_mock_cluster           /  0.016s] Produce to rdkafkatest_rnd4530a0fe0b07fa81_0009_mock_cluster [-1]: messages #0..100
[0009_mock_cluster           /  0.017s] SUM(POLL): duration 0.001ms
[0009_mock_cluster           /  0.017s] PRODUCE: duration 0.259ms
[0004_conf                   /  0.017s] Incremental S2F tests
[0004_conf                   /  0.017s]   Set: generic,broker,queue,cgrp
[0004_conf                   /  0.017s]   Now: generic,broker,queue,cgrp
[0004_conf                   /  0.017s]   Set: -broker,+queue,topic
[0004_conf                   /  0.017s]   Now: generic,topic,queue,cgrp
[0004_conf                   /  0.017s]   Set: -all,security,-fetch,+metadata
[0004_conf                   /  0.017s]   Now: metadata,security
[0004_conf                   /  0.017s] Error reporting for S2F properties
[0004_conf                   /  0.017s] Ok: Invalid value "invalid-value" for configuration property "debug"
[0004_conf                   /  0.017s] Canonical tests
[0004_conf                   /  0.017s]   Set: request.required.acks=0 expect 0 (topic)
[0004_conf                   /  0.017s]   Set: request.required.acks=-1 expect -1 (topic)
[0004_conf                   /  0.017s]   Set: request.required.acks=1 expect 1 (topic)
[0004_conf                   /  0.017s]   Set: acks=3 expect 3 (topic)
[0004_conf                   /  0.017s]   Set: request.required.acks=393 expect 393 (topic)
[0004_conf                   /  0.017s]   Set: request.required.acks=bad expect (null) (topic)
[0004_conf                   /  0.017s]   Set: request.required.acks=all expect -1 (topic)
[0004_conf                   /  0.017s]   Set: request.required.acks=all expect -1 (global)
[0004_conf                   /  0.017s]   Set: acks=0 expect 0 (topic)
[0004_conf                   /  0.017s]   Set: sasl.mechanisms=GSSAPI expect GSSAPI (global)
[0004_conf                   /  0.017s]   Set: sasl.mechanisms=PLAIN expect PLAIN (global)
[0004_conf                   /  0.017s]   Set: sasl.mechanisms=GSSAPI,PLAIN expect (null) (global)
[0004_conf                   /  0.017s]   Set: sasl.mechanisms= expect (null) (global)
[0004_conf                   /  0.018s]   Set: linger.ms=12555.3 expect 12555.3 (global)
[0004_conf                   /  0.018s]   Set: linger.ms=1500.000 expect 1500 (global)
[0004_conf                   /  0.018s]   Set: linger.ms=0.0001 expect 0.0001 (global)
[0004_conf                   /  0.019s] Ok: `acks` must be set to `all` when `enable.idempotence` is true
[0004_conf                   /  0.019s] Ok: Java TrustStores are not supported, use `ssl.ca.location` and a certificate file instead. See https://github.com/edenhill/librdkafka/wiki/Using-SSL-with-librdkafka for more information.
[0004_conf                   /  0.019s] Ok: Java JAAS configuration is not supported, see https://github.com/edenhill/librdkafka/wiki/Using-SASL-with-librdkafka for more information.
[0004_conf                   /  0.019s] Ok: Internal property "interceptors" not settable
%3|1594295281.665|TOPICCONF|rdkafka#producer-10| [thrd:app]: Incompatible configuration settings for topic "mytopic": `acks` must be set to `all` when `enable.idempotence` is true
[0009_mock_cluster           /  0.021s] PRODUCE.DELIVERY.WAIT: duration 4.163ms
[0009_mock_cluster           /  0.021s] ASSIGN.PARTITIONS: duration 0.187ms
[0009_mock_cluster           /  0.021s] CONSUME: assigned 4 partition(s)
[0009_mock_cluster           /  0.021s] CONSUME: consume 100 messages
%3|1594295281.667|TOPICCONF|rdkafka#producer-13| [thrd:app]: Incompatible configuration settings for topic "mytopic": `queuing.strategy` must be set to `fifo` when `enable.idempotence` is true
[0004_conf                   /  0.022s] Instance config linger.ms=123
[0004_conf                   /  0.022s] Instance config group.id=test1
[0004_conf                   /  0.022s] Instance config enable.auto.commit=false
[0004_conf                   /  0.023s] 0004_conf: duration 22.754ms
[0004_conf                   /  0.023s] ================= Test 0004_conf PASSED =================
[<MAIN>                      /  0.024s] Too many tests running (5 >= 5): postponing 0037_destroy_hang_local start...
[0033_regex_subscribe_local  /  0.000s] ================= Running test 0033_regex_subscribe_local =================
[0033_regex_subscribe_local  /  0.000s] ==== Stats written to file stats_0033_regex_subscribe_local_5116667560544761858.json ====
[0033_regex_subscribe_local  /  0.067s] 0033_regex_subscribe_local: duration 67.265ms
[0033_regex_subscribe_local  /  0.067s] ================= Test 0033_regex_subscribe_local PASSED =================
[<MAIN>                      /  0.092s] Too many tests running (5 >= 5): postponing 0043_no_connection start...
[0037_destroy_hang_local     /  0.000s] ================= Running test 0037_destroy_hang_local =================
[0037_destroy_hang_local     /  0.000s] ==== Stats written to file stats_0037_destroy_hang_local_1982582093981057734.json ====
[0037_destroy_hang_local     /  0.000s] Test config file test.conf not found
[0037_destroy_hang_local     /  0.000s] Setting test timeout to 30s * 2.7
[0037_destroy_hang_local     /  0.000s] Using topic "rdkafkatest_legacy_consumer_early_destroy"
[0037_destroy_hang_local     /  0.000s] legacy_consumer_early_destroy: pass #0
[0039_event                  /  0.000s] ================= Running test 0039_event =================
[0039_event                  /  0.000s] ==== Stats written to file stats_0039_event_8261407343716154427.json ====
[0037_destroy_hang_local     /  0.001s] Test config file test.conf not found
[0039_event                  /  0.001s] Created    kafka instance 0039_event#producer-16
[0037_destroy_hang_local     /  0.001s] Created    kafka instance 0037_destroy_hang_local#consumer-17
[0037_destroy_hang_local     /  0.002s] legacy_consumer_early_destroy: pass #1
[0037_destroy_hang_local     /  0.002s] Test config file test.conf not found
[0037_destroy_hang_local     /  0.002s] Created    kafka instance 0037_destroy_hang_local#consumer-18
[0039_event                  /  0.002s] Got Error event: _TRANSPORT: 0:65534/bootstrap: Connect to ipv4#0.0.0.0:65534 failed: Connection refused (after 1ms in state CONNECT)
[0039_event                  /  0.002s] Destroying kafka instance 0039_event#producer-16
[0039_event                  /  0.002s] 0039_event: duration 2.404ms
[0039_event                  /  0.002s] ================= Test 0039_event PASSED =================
[0025_timers                 /  0.114s] rd_kafka_poll(): duration 100.171ms
[<MAIN>                      /  0.196s] Too many tests running (5 >= 5): postponing 0046_rkt_cache start...
[0043_no_connection          /  0.000s] ================= Running test 0043_no_connection =================
[0043_no_connection          /  0.000s] ==== Stats written to file stats_0043_no_connection_7769656824735751995.json ====
[0043_no_connection          /  0.000s] Test config file test.conf not found
[0043_no_connection          /  0.000s] Setting test timeout to 20s * 2.7
[0043_no_connection          /  0.000s] Created    kafka instance 0043_no_connection#producer-19
[0043_no_connection          /  0.001s] Test config file test.conf not found
[0043_no_connection          /  0.001s] Produce to test_producer_no_connection [-1]: messages #0..100
[0043_no_connection          /  0.001s] SUM(POLL): duration 0.001ms
[0043_no_connection          /  0.001s] PRODUCE: duration 0.278ms
[0043_no_connection          /  0.001s] Produce to test_producer_no_connection [0]: messages #0..100
[0043_no_connection          /  0.001s] SUM(POLL): duration 0.000ms
[0043_no_connection          /  0.001s] PRODUCE: duration 0.292ms
[0043_no_connection          /  0.001s] Produce to test_producer_no_connection [1]: messages #0..100
[0043_no_connection          /  0.002s] SUM(POLL): duration 0.001ms
[0043_no_connection          /  0.002s] PRODUCE: duration 0.337ms
[0025_timers                 /  0.214s] rd_kafka_poll(): duration 100.115ms
[0025_timers                 /  0.315s] rd_kafka_poll(): duration 100.164ms
[0025_timers                 /  0.415s] rd_kafka_poll(): duration 100.166ms
[0025_timers                 /  0.515s] rd_kafka_poll(): duration 100.167ms
[0025_timers                 /  0.613s] Call #0: after 600ms, 0% outside interval 600  >-60 <+120
[0025_timers                 /  0.613s] rd_kafka_poll(): duration 98.455ms
[0025_timers                 /  0.714s] rd_kafka_poll(): duration 100.167ms
[0025_timers                 /  0.814s] rd_kafka_poll(): duration 100.192ms
[0025_timers                 /  0.914s] rd_kafka_poll(): duration 100.110ms
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 4315956 messages into destq with 165288 messages
[0025_timers                 /  1.014s] rd_kafka_poll(): duration 100.163ms
[0037_destroy_hang_local     /  1.003s] 0037_destroy_hang_local: duration 1002.803ms
[0037_destroy_hang_local     /  1.003s] ================= Test 0037_destroy_hang_local PASSED =================
[0025_timers                 /  1.114s] rd_kafka_poll(): duration 100.086ms
[<MAIN>                      /  1.196s] Too many tests running (5 >= 5): postponing 0053_stats_timing start...
[0046_rkt_cache              /  0.000s] ================= Running test 0046_rkt_cache =================
[0046_rkt_cache              /  0.000s] ==== Stats written to file stats_0046_rkt_cache_7777792445447508859.json ====
[0046_rkt_cache              /  0.000s] Using topic "rdkafkatest_0046_rkt_cache"
[0046_rkt_cache              /  0.000s] Test config file test.conf not found
[0046_rkt_cache              /  0.001s] Created    kafka instance 0046_rkt_cache#producer-20
[0046_rkt_cache              /  0.001s] Test config file test.conf not found
[0046_rkt_cache              /  0.001s] 0046_rkt_cache: duration 1.189ms
[0046_rkt_cache              /  0.001s] ================= Test 0046_rkt_cache PASSED =================
[0043_no_connection          /  1.002s] 300 messages in queue
[0043_no_connection          /  1.003s] rd_kafka_destroy(): duration 0.856ms
[0043_no_connection          /  1.003s] 0043_no_connection: duration 1002.681ms
[0043_no_connection          /  1.003s] ================= Test 0043_no_connection PASSED =================
[<MAIN>                      /  1.199s] Too many tests running (5 >= 5): postponing 0058_log start...
[0053_stats_timing           /  0.000s] ================= Running test 0053_stats_timing =================
[0053_stats_timing           /  0.000s] ==== Stats written to file stats_0053_stats_timing_5609471577866826912.json ====
[0025_timers                 /  1.213s] Call #1: after 600ms, 0% outside interval 600  >-60 <+120
[0025_timers                 /  1.213s] rd_kafka_poll(): duration 98.961ms
[<MAIN>                      /  1.299s] Too many tests running (5 >= 5): postponing 0062_stats_event start...
[0058_log                    /  0.000s] ================= Running test 0058_log =================
[0058_log                    /  0.000s] ==== Stats written to file stats_0058_log_671304013278455109.json ====
[0053_stats_timing           /  0.100s] Stats (#0): { "name": "rdkafka#producer-21", "client_id": "rdkafka", "type": "producer", "ts":3648779826481, "time":1594295282, "replyq":0, "msg_cnt":0, "msg_size":0, "msg_max":100000, "msg_size_max":1073741824, "simple_cnt":0, "metadata_cache_cnt":0, "brokers":{ }, "topics":{ } , "tx":0, "tx_bytes":0, "rx":0, "rx_bytes":0, "txmsgs":0, "txmsg_bytes":0, "rxmsgs":0, "rxmsg_bytes":0}
[0058_log                    /  0.000s] main.queue: Creating producer, not expecting any log messages
[0025_timers                 /  1.314s] rd_kafka_poll(): duration 100.185ms
[0025_timers                 /  1.414s] rd_kafka_poll(): duration 100.187ms
[0025_timers                 /  1.514s] rd_kafka_poll(): duration 100.161ms
[0025_timers                 /  1.614s] rd_kafka_poll(): duration 100.162ms
[0025_timers                 /  1.715s] rd_kafka_poll(): duration 100.114ms
[0025_timers                 /  1.814s] Call #2: after 600ms, 0% outside interval 600  >-60 <+120
[0025_timers                 /  1.814s] rd_kafka_poll(): duration 98.989ms
[0025_timers                 /  1.914s] rd_kafka_poll(): duration 100.215ms
[0025_timers                 /  2.014s] rd_kafka_poll(): duration 100.142ms
[0009_mock_cluster           /  2.017s] CONSUME: duration 1996.503ms
[0009_mock_cluster           /  2.018s] CONSUME: consumed 100/100 messages (0/-1 EOFs)
[0009_mock_cluster           /  2.022s] 0009_mock_cluster: duration 2022.148ms
[0009_mock_cluster           /  2.022s] ================= Test 0009_mock_cluster PASSED =================
[0025_timers                 /  2.114s] rd_kafka_poll(): duration 100.084ms
[<MAIN>                      /  2.124s] Too many tests running (5 >= 5): postponing 0066_plugins start...
[0062_stats_event            /  0.000s] ================= Running test 0062_stats_event =================
[0062_stats_event            /  0.000s] ==== Stats written to file stats_0062_stats_event_254574704057284607.json ====
[0062_stats_event            /  0.000s] Test config file test.conf not found
[0062_stats_event            /  0.000s] Setting test timeout to 10s * 2.7
[0062_stats_event            /  0.001s] Created    kafka instance 0062_stats_event#producer-23
[0025_timers                 /  2.214s] rd_kafka_poll(): duration 100.154ms
[0062_stats_event            /  0.101s] Stats event
[0062_stats_event            /  0.101s] Stats: { "name": "0062_stats_event#producer-23", "client_id": "0062_stats_event", "type": "producer", "ts":3648780751588, "time":1594295283, "replyq":0, "msg_cnt":0, "msg_size":0, "msg_max":100000, "msg_size_max":1073741824, "simple_cnt":0, "metadata_cache_cnt":0, "brokers":{ }, "topics":{ } , "tx":0, "tx_bytes":0, "rx":0, "rx_bytes":0, "txmsgs":0, "txmsg_bytes":0, "rxmsgs":0, "rxmsg_bytes":0}
[0062_stats_event            /  0.101s] STATS_EVENT: duration 100.104ms
[0058_log                    /  1.001s] main.queue: Setting log queue
[0058_log                    /  1.001s] main.queue: Expecting at least one log message
[0053_stats_timing           /  1.101s] Stats (#10): { "name": "rdkafka#producer-21", "client_id": "rdkafka", "type": "producer", "ts":3648780827436, "time":1594295283, "replyq":0, "msg_cnt":0, "msg_size":0, "msg_max":100000, "msg_size_max":1073741824, "simple_cnt":0, "metadata_cache_cnt":0, "brokers":{ }, "topics":{ } , "tx":0, "tx_bytes":0, "rx":0, "rx_bytes":0, "txmsgs":0, "txmsg_bytes":0, "rxmsgs":0, "rxmsg_bytes":0}
[0058_log                    /  1.001s] Log: level 7, facility INIT, str [thrd:app]: librdkafka v1.4.4-devel (0x10404ff) 0058_log#producer-22 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_gssapi,sasl_plain,sasl_scram,plugins,zstd,sasl_oauthbearer, CMAKE GNU GNU PKGCONFIG HDRHISTOGRAM ZLIB ZSTD LIBDL PLUGINS SSL SASL_SCRAM SASL_OAUTHBEARER SASL_CYRUS LZ4_EXT C11THREADS CRC32C_HW SNAPPY SOCKEM, debug 0x1)
[0058_log                    /  1.001s] main.queue: Saw 1 logs
[0058_log                    /  1.002s] local.queue: Creating producer, not expecting any log messages
[0025_timers                 /  2.315s] rd_kafka_poll(): duration 100.150ms
[0062_stats_event            /  0.201s] Stats event
[0062_stats_event            /  0.201s] Stats: { "name": "0062_stats_event#producer-23", "client_id": "0062_stats_event", "type": "producer", "ts":3648780851788, "time":1594295283, "replyq":0, "msg_cnt":0, "msg_size":0, "msg_max":100000, "msg_size_max":1073741824, "simple_cnt":0, "metadata_cache_cnt":0, "brokers":{ }, "topics":{ } , "tx":0, "tx_bytes":0, "rx":0, "rx_bytes":0, "txmsgs":0, "txmsg_bytes":0, "rxmsgs":0, "rxmsg_bytes":0}
[0062_stats_event            /  0.201s] STATS_EVENT: duration 100.148ms
[0053_stats_timing           /  1.201s] 12 (expected 12) stats callbacks received in 1200ms (expected 1200ms +-25%)
[0053_stats_timing           /  1.202s] 0053_stats_timing: duration 1201.911ms
[0053_stats_timing           /  1.202s] ================= Test 0053_stats_timing PASSED =================
[0025_timers                 /  2.414s] Call #3: after 600ms, 0% outside interval 600  >-60 <+120
[0025_timers                 /  2.414s] rd_kafka_poll(): duration 99.024ms
[0062_stats_event            /  0.301s] Stats event
[0062_stats_event            /  0.301s] Stats: { "name": "0062_stats_event#producer-23", "client_id": "0062_stats_event", "type": "producer", "ts":3648780951823, "time":1594295284, "replyq":0, "msg_cnt":0, "msg_size":0, "msg_max":100000, "msg_size_max":1073741824, "simple_cnt":0, "metadata_cache_cnt":0, "brokers":{ }, "topics":{ } , "tx":0, "tx_bytes":0, "rx":0, "rx_bytes":0, "txmsgs":0, "txmsg_bytes":0, "rxmsgs":0, "rxmsg_bytes":0}
[0062_stats_event            /  0.301s] STATS_EVENT: duration 100.012ms
[<MAIN>                      /  2.502s] Too many tests running (5 >= 5): postponing 0072_headers_ut start...
[0066_plugins                /  0.000s] ================= Running test 0066_plugins =================
[0066_plugins                /  0.000s] ==== Stats written to file stats_0066_plugins_4462217056028814564.json ====
[0066_plugins                /  0.000s] Using topic "rdkafkatest_rnd720d367d531402b0_0066_plugins"
[0066_plugins                /  0.000s] running test from cwd /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/x86_64-redhat-linux-gnu/tests
[0066_plugins                /  0.000s] set(session.timeout.ms, 6000)
[0066_plugins                /  0.000s] set(plugin.library.paths, interceptor_test/interceptor_test)
[0066_plugins                /  0.001s] conf_init(conf 0x7f4bc0000d00) called (setting opaque to 0x7f4c1c269034)
[0066_plugins                /  0.001s] conf_init0(conf 0x7f4bc0000d00) for ici 0x7f4bc0001580 with ici->conf 0x7f4bc0002440
[0066_plugins                /  0.001s] set(socket.timeout.ms, 12)
[0066_plugins                /  0.001s] on_conf_set(conf 0x7f4bc0000d00, "socket.timeout.ms", "12"): 0x7f4bc0001580
[0066_plugins                /  0.001s] on_conf_set(conf 0x7f4bc0000d00, "socket.timeout.ms", "12"): 0x7f4bc0001580
[0066_plugins                /  0.001s] set(interceptor_test.config1, one)
[0066_plugins                /  0.001s] on_conf_set(conf 0x7f4bc0000d00, "interceptor_test.config1", "one"): 0x7f4bc0001580
[0066_plugins                /  0.001s] on_conf_set(conf 0x7f4bc0000d00, interceptor_test.config1, one): 0x7f4bc0001580
[0066_plugins                /  0.001s] set(interceptor_test.config2, two)
[0066_plugins                /  0.001s] on_conf_set(conf 0x7f4bc0000d00, "interceptor_test.config2", "two"): 0x7f4bc0001580
[0066_plugins                /  0.001s] set(topic.metadata.refresh.interval.ms, 1234)
[0066_plugins                /  0.001s] on_conf_dup(new_conf 0x7f4bc0003270, old_conf 0x7f4bc0000d00, filter_cnt 0, ici 0x7f4bc0001580)
[0066_plugins                /  0.001s] conf_init0(conf 0x7f4bc0003270) for ici 0x7f4bc0003a90 with ici->conf 0x7f4bc0003ac0
[0066_plugins                /  0.001s] on_conf_set(conf 0x7f4bc0003270, "socket.timeout.ms", "12"): 0x7f4bc0003a90
[0066_plugins                /  0.001s] conf_init(conf 0x7f4bc0003ac0) called (setting opaque to 0x7f4c1c269034)
[0066_plugins                /  0.001s] conf_init0(conf 0x7f4bc0003ac0) for ici 0x7f4bc0004870 with ici->conf 0x7f4bc00048a0
[0066_plugins                /  0.001s] conf_init(conf 0x7f4bc0003270) called (setting opaque to 0x7f4c1c269034)
[0066_plugins                /  0.002s] on_conf_dup(new_conf 0x7f4bc00056c0, old_conf 0x7f4bc0003270, filter_cnt 2, ici 0x7f4bc0003a90)
[0066_plugins                /  0.002s] conf_init0(conf 0x7f4bc00056c0) for ici 0x7f4bc0005ee0 with ici->conf 0x7f4bc0005f10
[0066_plugins                /  0.002s] on_conf_set(conf 0x7f4bc00056c0, "socket.timeout.ms", "12"): 0x7f4bc0005ee0
[0066_plugins                /  0.002s] conf_init0(conf 0x7f4bc0003270) for ici 0x7f4bc0005690 with ici->conf 0x7f4bc00056c0
[0066_plugins                /  0.002s] on_conf_set(conf 0x7f4bc0003270, "interceptor_test.config1", "one"): 0x7f4bc0003a90
[0066_plugins                /  0.002s] on_conf_set(conf 0x7f4bc0003270, interceptor_test.config1, one): 0x7f4bc0003a90
[0066_plugins                /  0.002s] on_conf_set(conf 0x7f4bc0003270, "interceptor_test.config2", "two"): 0x7f4bc0003a90
[0066_plugins                /  0.002s] on_conf_set(conf 0x7f4bc0003270, "session.timeout.ms", "6000"): 0x7f4bc0003a90
[0066_plugins                /  0.002s] on_conf_set(conf 0x7f4bc0003ac0, "session.timeout.ms", "6000"): 0x7f4bc0004870
[0066_plugins                /  0.002s] on_conf_set(conf 0x7f4bc0003ac0, "session.timeout.ms", "6000"): 0x7f4bc0004870
[0066_plugins                /  0.002s] on_new(rk 0x7f4bc0006de0, conf 0x7f4bc0006f18, ici->conf 0x7f4bc0003ac0): 0x7f4bc0003a90: #1
[0066_plugins                /  0.003s] 0066_plugins: duration 3.006ms
[0066_plugins                /  0.003s] ================= Test 0066_plugins PASSED =================
[0025_timers                 /  2.514s] rd_kafka_poll(): duration 100.148ms
[0062_stats_event            /  0.401s] Stats event
[0062_stats_event            /  0.401s] Stats: { "name": "0062_stats_event#producer-23", "client_id": "0062_stats_event", "type": "producer", "ts":3648781051857, "time":1594295284, "replyq":0, "msg_cnt":0, "msg_size":0, "msg_max":100000, "msg_size_max":1073741824, "simple_cnt":0, "metadata_cache_cnt":0, "brokers":{ }, "topics":{ } , "tx":0, "tx_bytes":0, "rx":0, "rx_bytes":0, "txmsgs":0, "txmsg_bytes":0, "rxmsgs":0, "rxmsg_bytes":0}
[0062_stats_event            /  0.401s] STATS_EVENT: duration 100.020ms
[<MAIN>                      /  2.606s] Too many tests running (5 >= 5): postponing 0074_producev start...
[0072_headers_ut             /  0.000s] ================= Running test 0072_headers_ut =================
[0072_headers_ut             /  0.000s] ==== Stats written to file stats_0072_headers_ut_3767219167191773373.json ====
[0072_headers_ut             /  0.000s] Using topic "rdkafkatest_0072_headers_ut"
[0072_headers_ut             /  0.000s] Created    kafka instance 0072_headers_ut#producer-26
[0025_timers                 /  2.614s] rd_kafka_poll(): duration 100.156ms
[0062_stats_event            /  0.501s] Stats event
[0062_stats_event            /  0.501s] Stats: { "name": "0062_stats_event#producer-23", "client_id": "0062_stats_event", "type": "producer", "ts":3648781152053, "time":1594295284, "replyq":0, "msg_cnt":0, "msg_size":0, "msg_max":100000, "msg_size_max":1073741824, "simple_cnt":0, "metadata_cache_cnt":0, "brokers":{ }, "topics":{ } , "tx":0, "tx_bytes":0, "rx":0, "rx_bytes":0, "txmsgs":0, "txmsg_bytes":0, "rxmsgs":0, "rxmsg_bytes":0}
[0062_stats_event            /  0.501s] STATS_EVENT: duration 100.180ms
[0062_stats_event            /  0.502s] 0062_stats_event: duration 501.535ms
[0062_stats_event            /  0.502s] ================= Test 0062_stats_event PASSED =================
[0025_timers                 /  2.714s] rd_kafka_poll(): duration 100.149ms
[<MAIN>                      /  2.726s] Too many tests running (5 >= 5): postponing 0078_c_from_cpp start...
[0074_producev               /  0.000s] ================= Running test 0074_producev =================
[0074_producev               /  0.000s] ==== Stats written to file stats_0074_producev_2313503952925265912.json ====
[0074_producev               /  0.000s] Created    kafka instance 0074_producev#producer-27
[0074_producev               /  0.001s] 0074_producev: duration 0.737ms
[0074_producev               /  0.001s] ================= Test 0074_producev PASSED =================
[0025_timers                 /  2.814s] rd_kafka_poll(): duration 100.148ms
[0079_fork                   /  0.000s] WARN: SKIPPING TEST: Filtered due to negative test flags
[<MAIN>                      /  2.828s] Too many tests running (5 >= 5): postponing 0080_admin_ut start...
[0078_c_from_cpp             /  0.000s] ================= Running test 0078_c_from_cpp =================
[0078_c_from_cpp             /  0.000s] ==== Stats written to file stats_0078_c_from_cpp_5496579360920141855.json ====
[0078_c_from_cpp             /  0.000s] Compare C name myclient#producer-28 to C++ name myclient#producer-28
[0078_c_from_cpp             /  0.000s] Compare C topic mytopic to C++ topic mytopic
[0078_c_from_cpp             /  0.001s] 0078_c_from_cpp: duration 0.844ms
[0078_c_from_cpp             /  0.001s] ================= Test 0078_c_from_cpp PASSED =================
[0025_timers                 /  2.915s] rd_kafka_poll(): duration 100.151ms
[<MAIN>                      /  2.930s] Too many tests running (5 >= 5): postponing 0084_destroy_flags_local start...
[0080_admin_ut               /  0.000s] ================= Running test 0080_admin_ut =================
[0080_admin_ut               /  0.000s] ==== Stats written to file stats_0080_admin_ut_7167874086614204376.json ====
[0080_admin_ut               /  0.000s] Test config file test.conf not found
[0080_admin_ut               /  0.001s] [ Test unclean destroy for 0080_admin_ut#producer-29 using tempq]
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 2024402us, 0.4518us/msg
[0025_timers                 /  3.014s] Call #4: after 600ms, 0% outside interval 600  >-60 <+120
[0025_timers                 /  3.014s] rd_kafka_poll(): duration 99.023ms
[0080_admin_ut               /  0.101s] Giving rd_kafka_destroy() 5s to finish, despite Admin API request being processed
[0080_admin_ut               /  0.101s] Setting test timeout to 5s * 2.7
[0080_admin_ut               /  0.101s] rd_kafka_destroy(): duration 0.483ms
[0080_admin_ut               /  0.101s] Setting test timeout to 60s * 2.7
[0080_admin_ut               /  0.101s] Test config file test.conf not found
[0080_admin_ut               /  0.102s] [ Test unclean destroy for 0080_admin_ut#producer-30 using mainq]
[0025_timers                 /  3.114s] rd_kafka_poll(): duration 100.155ms
[0080_admin_ut               /  0.202s] Giving rd_kafka_destroy() 5s to finish, despite Admin API request being processed
[0080_admin_ut               /  0.202s] Setting test timeout to 5s * 2.7
[0080_admin_ut               /  0.203s] rd_kafka_destroy(): duration 0.575ms
[0080_admin_ut               /  0.203s] Setting test timeout to 60s * 2.7
[0080_admin_ut               /  0.203s] Test config file test.conf not found
[0080_admin_ut               /  0.203s] [ 0080_admin_ut#producer-31 CreateTopics with temp queue, no options, timeout 100ms ]
[0080_admin_ut               /  0.203s] Using topic "rdkafkatest_rnd4a26c173337def9d_do_test_CreateTopics"
[0080_admin_ut               /  0.203s] Using topic "rdkafkatest_rnd5377b4e4333f94e2_do_test_CreateTopics"
[0080_admin_ut               /  0.203s] Using topic "rdkafkatest_rnd58d1a0582a851466_do_test_CreateTopics"
[0080_admin_ut               /  0.203s] Using topic "rdkafkatest_rndcf418577f281715_do_test_CreateTopics"
[0080_admin_ut               /  0.204s] Using topic "rdkafkatest_rnd4ae1131d467183f9_do_test_CreateTopics"
[0080_admin_ut               /  0.204s] Using topic "rdkafkatest_rnd1df515cd390139b8_do_test_CreateTopics"
[0080_admin_ut               /  0.204s] Call CreateTopics, timeout is 100ms
[0080_admin_ut               /  0.204s] CreateTopics: duration 0.518ms
[0025_timers                 /  3.214s] rd_kafka_poll(): duration 100.151ms
[0080_admin_ut               /  0.304s] CreateTopics.queue_poll: duration 99.590ms
[0080_admin_ut               /  0.304s] CreateTopics: got CreateTopicsResult in 99.590s
[0080_admin_ut               /  0.304s] [ 0080_admin_ut#producer-31 CreateTopics with temp queue, no options, background_event_cb, timeout 100ms ]
[0080_admin_ut               /  0.304s] Using topic "rdkafkatest_rnd1977468b26d612dc_do_test_CreateTopics"
[0080_admin_ut               /  0.304s] Using topic "rdkafkatest_rnde09d68363d97878_do_test_CreateTopics"
[0080_admin_ut               /  0.304s] Using topic "rdkafkatest_rndd6d56a274371c38_do_test_CreateTopics"
[0080_admin_ut               /  0.304s] Using topic "rdkafkatest_rnd44cb567b708504fd_do_test_CreateTopics"
[0080_admin_ut               /  0.304s] Using topic "rdkafkatest_rnd301984f03aabc671_do_test_CreateTopics"
[0080_admin_ut               /  0.305s] Using topic "rdkafkatest_rnd5f2e056a0e237b55_do_test_CreateTopics"
[0080_admin_ut               /  0.305s] Call CreateTopics, timeout is 100ms
[0080_admin_ut               /  0.305s] CreateTopics: duration 0.361ms
[0058_log                    /  2.002s] local.queue: Setting log queue
[0058_log                    /  2.002s] local.queue: Expecting at least one log message
[0058_log                    /  2.002s] Log: level 7, facility INIT, str [thrd:app]: librdkafka v1.4.4-devel (0x10404ff) 0058_log#producer-24 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_gssapi,sasl_plain,sasl_scram,plugins,zstd,sasl_oauthbearer, CMAKE GNU GNU PKGCONFIG HDRHISTOGRAM ZLIB ZSTD LIBDL PLUGINS SSL SASL_SCRAM SASL_OAUTHBEARER SASL_CYRUS LZ4_EXT C11THREADS CRC32C_HW SNAPPY SOCKEM, debug 0x1)
[0058_log                    /  2.002s] local.queue: Saw 1 logs
[0058_log                    /  2.003s] 0058_log: duration 2003.217ms
[0058_log                    /  2.003s] ================= Test 0058_log PASSED =================
[0025_timers                 /  3.314s] rd_kafka_poll(): duration 100.096ms
[0080_admin_ut               /  0.405s] CreateTopics.wait_background_event_cb: duration 99.947ms
[0080_admin_ut               /  0.405s] CreateTopics: got CreateTopicsResult in 99.947s
[0080_admin_ut               /  0.405s] [ 0080_admin_ut#producer-31 CreateTopics with temp queue, options, timeout 100ms ]
[0080_admin_ut               /  0.405s] Using topic "rdkafkatest_rnd190ae5f366f51bad_do_test_CreateTopics"
[0080_admin_ut               /  0.405s] Using topic "rdkafkatest_rnd567034d573e93405_do_test_CreateTopics"
[0080_admin_ut               /  0.405s] Using topic "rdkafkatest_rnd32e17df83eca4722_do_test_CreateTopics"
[0080_admin_ut               /  0.405s] Using topic "rdkafkatest_rnd15ffd995cbf5cef_do_test_CreateTopics"
[0080_admin_ut               /  0.406s] Using topic "rdkafkatest_rnd42657197636a37a_do_test_CreateTopics"
[0080_admin_ut               /  0.406s] Using topic "rdkafkatest_rnd2707e82f044079fe_do_test_CreateTopics"
[0080_admin_ut               /  0.406s] Call CreateTopics, timeout is 200ms
[0025_timers                 /  3.414s] rd_kafka_poll(): duration 100.076ms
[0025_timers                 /  3.514s] rd_kafka_poll(): duration 100.071ms
[<MAIN>                      /  3.522s] Too many tests running (5 >= 5): postponing 0086_purge_local start...
[0084_destroy_flags_local    /  0.000s] ================= Running test 0084_destroy_flags_local =================
[0084_destroy_flags_local    /  0.000s] ==== Stats written to file stats_0084_destroy_flags_local_1599128698121736352.json ====
[0084_destroy_flags_local    /  0.000s] Using topic "rdkafkatest_rndc7dce9d68d3fd7a_destroy_flags"
[0084_destroy_flags_local    /  0.000s] [ test destroy_flags 0x0 for client_type 0, produce_cnt 0, subscribe 0, unsubscribe 0, local mode ]
[0084_destroy_flags_local    /  0.000s] Test config file test.conf not found
[0084_destroy_flags_local    /  0.000s] Setting test timeout to 20s * 2.7
[0025_timers                 /  3.615s] rd_kafka_poll(): duration 100.072ms
[0025_timers                 /  3.715s] rd_kafka_poll(): duration 100.151ms
[0025_timers                 /  3.815s] rd_kafka_poll(): duration 100.159ms
[0080_admin_ut               /  0.889s] CreateTopics: duration 483.513ms
[0025_timers                 /  3.818s] Call #5: after 804ms, 34% outside interval 600  >-60 <+120
[0084_destroy_flags_local    /  0.297s] Created    kafka instance 0084_destroy_flags_local#producer-32
[0084_destroy_flags_local    /  0.297s] Calling rd_kafka_destroy_flags(0x0)
[0025_timers                 /  3.818s] WARN: ^ outside range
[0025_timers                 /  3.818s] rd_kafka_poll(): duration 2.914ms
[0080_admin_ut               /  0.890s] TEST FAILURE
### Test "0080_admin_ut" failed at /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/tests/0080-admin_ut.c:217:do_test_CreateTopics() at Thu Jul  9 12:48:05 2020: ###
CreateTopics: expected duration 0 <= 483 <= 50 ms
[0080_admin_ut               /  0.890s] CreateTopics.queue_poll: duration 0.003ms
[0080_admin_ut               /  0.890s] TEST FAILURE
### Test "0080_admin_ut" failed at /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/tests/0080-admin_ut.c:230:do_test_CreateTopics() at Thu Jul  9 12:48:05 2020: ###
CreateTopics.queue_poll: expected duration 100 <= 0 <= 300 ms
[0080_admin_ut               /  0.890s] CreateTopics: got CreateTopicsResult in 0.003s
[0080_admin_ut               /  0.890s] [ 0080_admin_ut#producer-31 CreateTopics with main queue, options, timeout 100ms ]
[0080_admin_ut               /  0.890s] Using topic "rdkafkatest_rnd7d02d39a668db6dd_do_test_CreateTopics"
[0084_destroy_flags_local    /  0.298s] rd_kafka_destroy_flags(0x0): duration 0.567ms
[0080_admin_ut               /  0.890s] Using topic "rdkafkatest_rnd37ae9a0b17c55fdd_do_test_CreateTopics"
[0084_destroy_flags_local    /  0.298s] [ test destroy_flags 0x0 for client_type 0, produce_cnt 0, subscribe 0, unsubscribe 0, local mode: PASS ]
[0084_destroy_flags_local    /  0.298s] [0080_admin_ut               /  0.890s] Using topic "rdkafkatest_rnd45d215617c3c9dc0_do_test_CreateTopics"
[ test destroy_flags 0x8 for client_type 0, produce_cnt 0, subscribe 0, unsubscribe 0, local mode ]
[0072_headers_ut             /  1.215s] 0072_headers_ut: duration 1214.666ms
[0072_headers_ut             /  1.215s] ================= Test 0072_headers_ut PASSED =================
[0084_destroy_flags_local    /  0.298s] Test config file test.conf not found
[0084_destroy_flags_local    /  0.298s] Setting test timeout to 20s * 2.7
[0080_admin_ut               /  0.891s] Using topic "rdkafkatest_rnd2cc7310e0b38f00a_do_test_CreateTopics"
[0080_admin_ut               /  0.891s] Using topic "rdkafkatest_rnd20b06513195d5968_do_test_CreateTopics"
[0080_admin_ut               /  0.891s] Using topic "rdkafkatest_rnd6df346c0097d47d0_do_test_CreateTopics"
[0084_destroy_flags_local    /  0.299s] Created    kafka instance 0084_destroy_flags_local#producer-33
[0080_admin_ut               /  0.891s] Call CreateTopics, timeout is 200ms
[0084_destroy_flags_local    /  0.299s] Calling rd_kafka_destroy_flags(0x8)
[0080_admin_ut               /  0.892s] CreateTopics: duration 0.401ms
[0025_timers                 /  3.918s] rd_kafka_poll(): duration 100.158ms
[0084_destroy_flags_local    /  0.495s] rd_kafka_destroy_flags(0x8): duration 195.961ms
[0084_destroy_flags_local    /  0.495s] [ test destroy_flags 0x8 for client_type 0, produce_cnt 0, subscribe 0, unsubscribe 0, local mode: PASS ]
[0084_destroy_flags_local    /  0.495s] [ test destroy_flags 0x0 for client_type 0, produce_cnt 10000, subscribe 0, unsubscribe 0, local mode ]
[0084_destroy_flags_local    /  0.495s] Test config file test.conf not found
[0084_destroy_flags_local    /  0.495s] Setting test timeout to 20s * 2.7
[<MAIN>                      /  4.018s] Too many tests running (5 >= 5): postponing 0095_all_brokers_down start...
[0084_destroy_flags_local    /  0.495s] Created    kafka instance 0084_destroy_flags_local#producer-34
[0084_destroy_flags_local    /  0.495s] Test config file test.conf not found
[0084_destroy_flags_local    /  0.496s] Produce to rdkafkatest_rndc7dce9d68d3fd7a_destroy_flags [-1]: messages #0..10000
[0086_purge_local            /  0.000s] ================= Running test 0086_purge_local =================
[0086_purge_local            /  0.000s] ==== Stats written to file stats_0086_purge_local_8902048349505691370.json ====
[0086_purge_local            /  0.000s] Using topic "rdkafkatest_0086_purge"
[0086_purge_local            /  0.000s] Test rd_kafka_purge(): local
[0086_purge_local            /  0.000s] Test config file test.conf not found
[0086_purge_local            /  0.000s] Setting test timeout to 20s * 2.7
[0025_timers                 /  4.018s] rd_kafka_poll(): duration 100.152ms
[0080_admin_ut               /  1.091s] CreateTopics.queue_poll: duration 199.690ms
[0080_admin_ut               /  1.091s] CreateTopics: got CreateTopicsResult in 199.690s
[0080_admin_ut               /  1.092s] [ 0080_admin_ut#producer-31 DeleteTopics with temp queue, no options, timeout 100ms ]
[0080_admin_ut               /  1.092s] Using topic "rdkafkatest_rnd34ab871936b1269d_do_test_DeleteTopics"
[0080_admin_ut               /  1.092s] Using topic "rdkafkatest_rnd483e5a204adcc62d_do_test_DeleteTopics"
[0080_admin_ut               /  1.092s] Using topic "rdkafkatest_rnd485ef73e54bc28bd_do_test_DeleteTopics"
[0080_admin_ut               /  1.092s] Using topic "rdkafkatest_rnd33b0c3a71ed81e59_do_test_DeleteTopics"
[0080_admin_ut               /  1.092s] Call DeleteTopics, timeout is 100ms
[0080_admin_ut               /  1.092s] DeleteTopics: duration 0.037ms
[0025_timers                 /  4.119s] rd_kafka_poll(): duration 100.126ms
%4|1594295285.766|CONFWARN|0086_purge_local#producer-35| [thrd:app]: Configuration property enable.gapless.guarantee is experimental: When set to `true`, any error that could result in a gap in the produced message series when a batch of messages fails, will raise a fatal error (ERR__GAPLESS_GUARANTEE) and stop the producer. Messages failing due to `message.timeout.ms` are not covered by this guarantee. Requires `enable.idempotence=true`.
[0086_purge_local            /  0.103s] Created    kafka instance 0086_purge_local#producer-35
[0086_purge_local            /  0.103s] Producing 20 messages to topic rdkafkatest_0086_purge
[0086_purge_local            /  0.103s] local:279: purge(0x2): expecting 20 messages to remain when done
[0086_purge_local            /  0.104s] local:279: purge(0x2): duration 0.104ms
[0086_purge_local            /  0.104s] local:283: purge(0x1): expecting 0 messages to remain when done
[0086_purge_local            /  0.104s] local:283: purge(0x1): duration 0.052ms
[0086_purge_local            /  0.104s] DeliveryReport for msg #0: _PURGE_QUEUE
[0086_purge_local            /  0.104s] DeliveryReport for msg #1: _PURGE_QUEUE
[0086_purge_local            /  0.104s] DeliveryReport for msg #2: _PURGE_QUEUE
[0086_purge_local            /  0.104s] DeliveryReport for msg #3: _PURGE_QUEUE
[0086_purge_local            /  0.104s] DeliveryReport for msg #4: _PURGE_QUEUE
[0086_purge_local            /  0.104s] DeliveryReport for msg #5: _PURGE_QUEUE
[0086_purge_local            /  0.104s] DeliveryReport for msg #6: _PURGE_QUEUE
[0086_purge_local            /  0.104s] [0080_admin_ut               /  1.192s] DeleteTopics.queue_poll: duration 100.040ms
DeliveryReport for msg #7: _PURGE_QUEUE
[0086_purge_local            /  0.104s] DeliveryReport for msg #8: _PURGE_QUEUE
[0086_purge_local            /  0.104s] DeliveryReport for msg #9: _PURGE_QUEUE
[0086_purge_local            /  0.104s] DeliveryReport for msg #10: _PURGE_QUEUE
[0080_admin_ut               /  1.192s] DeleteTopics: got DeleteTopicsResult in 100.040s
[0086_purge_local            /  0.104s] DeliveryReport for msg #11: _PURGE_QUEUE
[0086_purge_local            /  0.104s] DeliveryReport for msg #12: _PURGE_QUEUE
[0080_admin_ut               /  1.192s] [ 0080_admin_ut#producer-31 DeleteTopics with temp queue, options, timeout 100ms ]
[0086_purge_local            /  0.104s] DeliveryReport for msg #13: _PURGE_QUEUE
[0086_purge_local            /  0.104s] DeliveryReport for msg #14: _PURGE_QUEUE
[0086_purge_local            /  0.105s] DeliveryReport for msg #15: _PURGE_QUEUE
[0080_admin_ut               /  1.193s] Using topic "rdkafkatest_rnd51befc571a3e7a84_do_test_DeleteTopics"
[0086_purge_local            /  0.105s] DeliveryReport for msg #16: _PURGE_QUEUE
[0086_purge_local            /  0.105s] DeliveryReport for msg #17: _PURGE_QUEUE
[0080_admin_ut               /  1.193s] Using topic "rdkafkatest_rnd256aca65096d9663_do_test_DeleteTopics"
[0086_purge_local            /  0.105s] DeliveryReport for msg #18: _PURGE_QUEUE
[0080_admin_ut               /  1.193s] Using topic "rdkafkatest_rnd3203da620b2b7bdb_do_test_DeleteTopics"
[0080_admin_ut               /  1.193s] Using topic "rdkafkatest_rnd4f3fabc42e407822_do_test_DeleteTopics"
[0086_purge_local            /  0.105s] DeliveryReport for msg #19: _PURGE_QUEUE
[0080_admin_ut               /  1.193s] Call DeleteTopics, timeout is 200ms
[0080_admin_ut               /  1.193s] DeleteTopics: duration 0.141ms
[0025_timers                 /  4.219s] rd_kafka_poll(): duration 100.083ms
[0025_timers                 /  4.319s] rd_kafka_poll(): duration 100.074ms
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: many messages
[0080_admin_ut               /  1.397s] DeleteTopics.queue_poll: duration 203.551ms
[0080_admin_ut               /  1.397s] [0086_purge_local            /  0.309s] 0086_purge_local: duration 308.781ms
DeleteTopics: got DeleteTopicsResult in 203.551s
[0086_purge_local            /  0.309s] ================= Test 0086_purge_local PASSED =================
[0080_admin_ut               /  1.397s] [ 0080_admin_ut#producer-31 DeleteTopics with main queue, options, timeout 100ms ]
[0080_admin_ut               /  1.397s] Using topic "rdkafkatest_rnd9f713447c06dcd2_do_test_DeleteTopics"
[0080_admin_ut               /  1.397s] Using topic "rdkafkatest_rnd3979682c5f32df83_do_test_DeleteTopics"
[0080_admin_ut               /  1.397s] Using topic "rdkafkatest_rnd1cb741e652d6c195_do_test_DeleteTopics"
[0080_admin_ut               /  1.397s] Using topic "rdkafkatest_rnd675029ba7c31ee1b_do_test_DeleteTopics"
[0080_admin_ut               /  1.397s] Call DeleteTopics, timeout is 200ms
[0080_admin_ut               /  1.397s] DeleteTopics: duration 0.037ms
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 100001 messages into destq with 165288 messages
[0084_destroy_flags_local    /  0.831s] SUM(POLL): duration 0.001ms
[0084_destroy_flags_local    /  0.831s] PRODUCE: duration 334.938ms
[0084_destroy_flags_local    /  0.831s] Calling rd_kafka_destroy_flags(0x0)
[0084_destroy_flags_local    /  0.844s] rd_kafka_destroy_flags(0x0): duration 13.734ms
[0084_destroy_flags_local    /  0.844s] [ test destroy_flags 0x0 for client_type 0, produce_cnt 10000, subscribe 0, unsubscribe 0, local mode: PASS ]
[0084_destroy_flags_local    /  0.844s] [ test destroy_flags 0x8 for client_type 0, produce_cnt 10000, subscribe 0, unsubscribe 0, local mode ]
[0084_destroy_flags_local    /  0.844s] Test config file test.conf not found
[0084_destroy_flags_local    /  0.844s] Setting test timeout to 20s * 2.7
[0084_destroy_flags_local    /  0.845s] Created    kafka instance 0084_destroy_flags_local#producer-36
[0084_destroy_flags_local    /  0.845s] Test config file test.conf not found
[0084_destroy_flags_local    /  0.845s] Produce to rdkafkatest_rndc7dce9d68d3fd7a_destroy_flags [-1]: messages #0..10000
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 33652us, 0.3365us/msg
[0084_destroy_flags_local    /  0.862s] SUM(POLL): duration 0.000ms
[0084_destroy_flags_local    /  0.862s] PRODUCE: duration 17.373ms
[0084_destroy_flags_local    /  0.862s] Calling rd_kafka_destroy_flags(0x8)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 50001 messages into destq with 265289 messages
[0084_destroy_flags_local    /  0.877s] rd_kafka_destroy_flags(0x8): duration 14.592ms
[0084_destroy_flags_local    /  0.877s] [ test destroy_flags 0x8 for client_type 0, produce_cnt 10000, subscribe 0, unsubscribe 0, local mode: PASS ]
[0084_destroy_flags_local    /  0.877s] [ test destroy_flags 0x0 for client_type 1, produce_cnt 0, subscribe 1, unsubscribe 0, local mode ]
[0084_destroy_flags_local    /  0.877s] Test config file test.conf not found
[0084_destroy_flags_local    /  0.877s] Setting test timeout to 20s * 2.7
[0084_destroy_flags_local    /  0.877s] Created    kafka instance 0084_destroy_flags_local#consumer-37
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 22551us, 0.4510us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 20001 messages into destq with 315290 messages
[0025_timers                 /  4.418s] Call #6: after 600ms, 0% outside interval 600  >-60 <+120
[0025_timers                 /  4.418s] rd_kafka_poll(): duration 98.999ms
[<MAIN>                      /  4.428s] Too many tests running (5 >= 5): postponing 0100_thread_interceptors start...
[0095_all_brokers_down       /  0.000s] ================= Running test 0095_all_brokers_down =================
[0095_all_brokers_down       /  0.000s] ==== Stats written to file stats_0095_all_brokers_down_4347229439431610484.json ====
[0095_all_brokers_down       /  0.000s] Setting test timeout to 20s * 2.7
[0095_all_brokers_down       /  0.000s] Test Producer
[0095_all_brokers_down       /  0.003s] Error: Local: Broker transport failure: 127.0.0.1:2/bootstrap: Connect to ipv4#127.0.0.1:2 failed: Connection refused (after 1ms in state CONNECT)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 24142us, 1.2070us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 59129 messages into destq with 335291 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 28447us, 0.4811us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 86823 messages into destq with 394420 messages
[0025_timers                 /  4.518s] rd_kafka_poll(): duration 100.164ms
[0080_admin_ut               /  1.597s] DeleteTopics.queue_poll: duration 200.120ms
[0080_admin_ut               /  1.597s] DeleteTopics: got DeleteTopicsResult in 200.120s
[0080_admin_ut               /  1.597s] [ Mixed mode test on 0080_admin_ut#producer-31]
[0080_admin_ut               /  1.597s] Creating 2 topics
[0080_admin_ut               /  1.597s] Deleting 1 topics
[0080_admin_ut               /  1.598s] Creating 1 topics
[0080_admin_ut               /  1.598s] Creating (up to) 15 partitions for topic "topicD"
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 38609us, 0.4447us/msg
[0025_timers                 /  4.618s] rd_kafka_poll(): duration 100.161ms
[0080_admin_ut               /  1.698s] Got event CreateTopicsResult: Failed while waiting for controller: Local: Timed out
[0080_admin_ut               /  1.698s] Got event DeleteTopicsResult: Failed while waiting for controller: Local: Timed out
[0080_admin_ut               /  1.698s] Got event CreateTopicsResult: Failed while waiting for controller: Local: Timed out
[0080_admin_ut               /  1.698s] Got event CreatePartitionsResult: Failed while waiting for controller: Local: Timed out
[0025_timers                 /  4.718s] rd_kafka_poll(): duration 100.157ms
[0025_timers                 /  4.819s] rd_kafka_poll(): duration 100.156ms
[0084_destroy_flags_local    /  1.378s] Calling rd_kafka_destroy_flags(0x0)
[0084_destroy_flags_local    /  1.379s] rd_kafka_destroy_flags(0x0): duration 0.878ms
[0084_destroy_flags_local    /  1.379s] [ test destroy_flags 0x0 for client_type 1, produce_cnt 0, subscribe 1, unsubscribe 0, local mode: PASS ]
[0084_destroy_flags_local    /  1.379s] [ test destroy_flags 0x8 for client_type 1, produce_cnt 0, subscribe 1, unsubscribe 0, local mode ]
[0084_destroy_flags_local    /  1.379s] Test config file test.conf not found
[0084_destroy_flags_local    /  1.379s] Setting test timeout to 20s * 2.7
[0084_destroy_flags_local    /  1.380s] Created    kafka instance 0084_destroy_flags_local#consumer-39
[0025_timers                 /  4.919s] rd_kafka_poll(): duration 100.180ms
[0025_timers                 /  5.018s] Call #7: after 600ms, 0% outside interval 600  >-60 <+120
[0025_timers                 /  5.018s] rd_kafka_poll(): duration 99.013ms
[0025_timers                 /  5.118s] rd_kafka_poll(): duration 100.161ms
[0025_timers                 /  5.218s] rd_kafka_poll(): duration 100.157ms
[0025_timers                 /  5.319s] rd_kafka_poll(): duration 100.156ms
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 4000001 messages into destq with 481243 messages
[0084_destroy_flags_local    /  1.881s] Calling rd_kafka_destroy_flags(0x8)
[0084_destroy_flags_local    /  1.882s] rd_kafka_destroy_flags(0x8): duration 0.753ms
[0084_destroy_flags_local    /  1.882s] [ test destroy_flags 0x8 for client_type 1, produce_cnt 0, subscribe 1, unsubscribe 0, local mode: PASS ]
[0084_destroy_flags_local    /  1.882s] [ test destroy_flags 0x0 for client_type 1, produce_cnt 0, subscribe 1, unsubscribe 1, local mode ]
[0084_destroy_flags_local    /  1.882s] Test config file test.conf not found
[0084_destroy_flags_local    /  1.882s] Setting test timeout to 20s * 2.7
[0084_destroy_flags_local    /  1.882s] Created    kafka instance 0084_destroy_flags_local#consumer-40
[0025_timers                 /  5.419s] rd_kafka_poll(): duration 100.154ms
[0095_all_brokers_down       /  1.002s] Error: Local: Broker transport failure: 127.0.0.1:1/bootstrap: Connect to ipv4#127.0.0.1:1 failed: Connection refused (after 1ms in state CONNECT)
[0095_all_brokers_down       /  1.002s] Error: Local: All broker connections are down: 2/2 brokers are down
[0095_all_brokers_down       /  1.003s] Test KafkaConsumer
[0025_timers                 /  5.519s] rd_kafka_poll(): duration 100.155ms
[0025_timers                 /  5.618s] Call #8: after 600ms, 0% outside interval 600  >-60 <+120
[0025_timers                 /  5.618s] rd_kafka_poll(): duration 98.955ms
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 321545us, 0.0804us/msg
[0025_timers                 /  5.718s] rd_kafka_poll(): duration 100.148ms
[0025_timers                 /  5.818s] rd_kafka_poll(): duration 100.150ms
[0084_destroy_flags_local    /  2.383s] Calling rd_kafka_unsubscribe
[0084_destroy_flags_local    /  2.384s] Calling rd_kafka_destroy_flags(0x0)
[0084_destroy_flags_local    /  2.384s] rd_kafka_destroy_flags(0x0): duration 0.732ms
[0084_destroy_flags_local    /  2.384s] [ test destroy_flags 0x0 for client_type 1, produce_cnt 0, subscribe 1, unsubscribe 1, local mode: PASS ]
[0084_destroy_flags_local    /  2.384s] [ test destroy_flags 0x8 for client_type 1, produce_cnt 0, subscribe 1, unsubscribe 1, local mode ]
[0084_destroy_flags_local    /  2.385s] Test config file test.conf not found
[0084_destroy_flags_local    /  2.385s] Setting test timeout to 20s * 2.7
[0084_destroy_flags_local    /  2.385s] Created    kafka instance 0084_destroy_flags_local#consumer-42
[0025_timers                 /  5.919s] rd_kafka_poll(): duration 100.150ms
[0025_timers                 /  6.019s] rd_kafka_poll(): duration 100.150ms
[0025_timers                 /  6.119s] rd_kafka_poll(): duration 100.166ms
[0025_timers                 /  6.218s] Call #9: after 600ms, 0% outside interval 600  >-60 <+120
[0025_timers                 /  6.218s] rd_kafka_poll(): duration 99.057ms
[0025_timers                 /  6.219s] TEST FAILURE
### Test "0025_timers" failed at /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/tests/0025-timers.c:134:do_test_stats_timer() at Thu Jul  9 12:48:07 2020: ###
1/10 intervals failed
[<MAIN>                      /  6.231s] Too many tests running (5 >= 5): postponing 0103_transactions_local start...
[0100_thread_interceptors    /  0.000s] ================= Running test 0100_thread_interceptors =================
[0100_thread_interceptors    /  0.000s] ==== Stats written to file stats_0100_thread_interceptors_3725285287026028140.json ====
[0100_thread_interceptors    /  0.000s] on_conf_dup() interceptor called
[0100_thread_interceptors    /  0.000s] on_new() interceptor called
[<MAIN>                      /  6.232s] on_thread_start(0, main) called
[<MAIN>                      /  6.232s] Started thread: main
[0084_destroy_flags_local    /  2.886s] Calling rd_kafka_unsubscribe
[0084_destroy_flags_local    /  2.886s] Calling rd_kafka_destroy_flags(0x8)
[0095_all_brokers_down       /  2.004s] Error: Local: Broker transport failure: 127.0.0.1:1/bootstrap: Connect to ipv4#127.0.0.1:1 failed: Connection refused (after 1ms in state CONNECT)
[<MAIN>                      /  6.232s] on_thread_start(2, :0/internal) called
[<MAIN>                      /  6.550s] Started thread: :0/internal
[0084_destroy_flags_local    /  3.027s] rd_kafka_destroy_flags(0x8): duration 140.839ms
[0084_destroy_flags_local    /  3.027s] [ test destroy_flags 0x8 for client_type 1, produce_cnt 0, subscribe 1, unsubscribe 1, local mode: PASS ]
[0084_destroy_flags_local    /  3.027s] [ test destroy_flags 0x0 for client_type 1, produce_cnt 0, subscribe 0, unsubscribe 0, local mode ]
[<MAIN>                      /  6.550s] on_thread_start(2, 127.0.0.1:1/bootstrap) called
[0084_destroy_flags_local    /  3.027s] [<MAIN>                      /  6.550s] Test config file test.conf not found
Started thread: 127.0.0.1:1/bootstrap
[0084_destroy_flags_local    /  3.027s] Setting test timeout to 20s * 2.7
[0084_destroy_flags_local    /  3.028s] Created    kafka instance 0084_destroy_flags_local#consumer-44
%3|1594295288.196|FAIL|rdkafka#producer-43| [thrd:127.0.0.1:1/bootstrap]: 127.0.0.1:1/bootstrap: Connect to ipv4#127.0.0.1:1 failed: Connection refused (after 0ms in state CONNECT)
%3|1594295288.196|ERROR|rdkafka#producer-43| [thrd:127.0.0.1:1/bootstrap]: 127.0.0.1:1/bootstrap: Connect to ipv4#127.0.0.1:1 failed: Connection refused (after 0ms in state CONNECT)
%3|1594295288.196|ERROR|rdkafka#producer-43| [thrd:127.0.0.1:1/bootstrap]: 1/1 brokers are down
[0080_admin_ut               /  3.699s] Test config file test.conf not found
[0080_admin_ut               /  3.699s] [ Test unclean destroy for 0080_admin_ut#consumer-45 using tempq]
[0080_admin_ut               /  3.799s] Giving rd_kafka_destroy() 5s to finish, despite Admin API request being processed
[0080_admin_ut               /  3.799s] Setting test timeout to 5s * 2.7
[0080_admin_ut               /  3.800s] rd_kafka_destroy(): duration 0.510ms
[0080_admin_ut               /  3.800s] Setting test timeout to 60s * 2.7
[0080_admin_ut               /  3.800s] Test config file test.conf not found
[0080_admin_ut               /  3.800s] [ Test unclean destroy for 0080_admin_ut#consumer-46 using mainq]
[0080_admin_ut               /  3.900s] Giving rd_kafka_destroy() 5s to finish, despite Admin API request being processed
[0080_admin_ut               /  3.901s] Setting test timeout to 5s * 2.7
[0080_admin_ut               /  3.901s] rd_kafka_destroy(): duration 0.431ms
[0080_admin_ut               /  3.901s] Setting test timeout to 60s * 2.7
[0080_admin_ut               /  3.901s] Test config file test.conf not found
%4|1594295288.476|CONFWARN|0080_admin_ut#consumer-47| [thrd:app]: Configuration property `fetch.wait.max.ms` (100) should be set lower than `socket.timeout.ms` (100) by at least 1000ms to avoid blocking and timing out sub-sequent requests
[0080_admin_ut               /  3.902s] TEST FAILURE
### Test "0080_admin_ut" failed at /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/tests/0080-admin_ut.c:690:do_test_options() at Thu Jul  9 12:48:08 2020: ###
See previous errors.
[<MAIN>                      /  6.932s] Too many tests running (5 >= 5): postponing 0104_fetch_from_follower_mock start...
[0103_transactions_local     /  0.000s] ================= Running test 0103_transactions_local =================
[0103_transactions_local     /  0.000s] ==== Stats written to file stats_0103_transactions_local_76248177348155047.json ====
[0103_transactions_local     /  0.000s] Test config file test.conf not found
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 0.1087us/msg over 4315956 messages in 468946us
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: issue #2508
[0103_transactions_local     /  0.025s] Created    kafka instance 0103_transactions_local#producer-48
[0103_transactions_local     /  0.025s] Test config file test.conf not found
[0103_transactions_local     /  0.026s] Created    kafka instance 0103_transactions_local#producer-49
[0103_transactions_local     /  0.026s] Waiting for init_transactions() timeout 7000 ms
[0103_transactions_local     /  0.026s] Setting test timeout to 9s * 2.7
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 145952 messages into destq with 154875 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 45093us, 0.1499us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: issue #2508
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 59129 messages into destq with 154875 messages
[<MAIN>                      /  7.050s] on_thread_exit(0, main) called
[<MAIN>                      /  7.050s] Exiting from thread: main
[<MAIN>                      /  7.051s] on_thread_exit(2, 127.0.0.1:1/bootstrap) called
[<MAIN>                      /  7.051s] Exiting from thread: 127.0.0.1:1/bootstrap
[<MAIN>                      /  7.051s] on_thread_exit(2, :0/internal) called
[<MAIN>                      /  7.051s] Exiting from thread: :0/internal
[0100_thread_interceptors    /  0.820s] 3 thread start calls, 3 thread exit calls seen
[0100_thread_interceptors    /  0.820s] 0100_thread_interceptors: duration 819.892ms
[0100_thread_interceptors    /  0.820s] ================= Test 0100_thread_interceptors PASSED =================
[0084_destroy_flags_local    /  3.529s] Calling rd_kafka_destroy_flags(0x0)
[0084_destroy_flags_local    /  3.530s] rd_kafka_destroy_flags(0x0): duration 1.257ms
[0084_destroy_flags_local    /  3.530s] [ test destroy_flags 0x0 for client_type 1, produce_cnt 0, subscribe 0, unsubscribe 0, local mode: PASS ]
[0084_destroy_flags_local    /  3.530s] [ test destroy_flags 0x8 for client_type 1, produce_cnt 0, subscribe 0, unsubscribe 0, local mode ]
[0084_destroy_flags_local    /  3.530s] Test config file test.conf not found
[0084_destroy_flags_local    /  3.530s] Setting test timeout to 20s * 2.7
[0084_destroy_flags_local    /  3.531s] Created    kafka instance 0084_destroy_flags_local#consumer-50
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 13917us, 0.2354us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 86823 messages into destq with 214004 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 14835us, 0.1709us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 0.1970us/msg over 145952 messages in 28752us
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1849: unittest_msgq_insert_all_sort: Testing msgq insert (all) efficiency: issue #2450 (v1.2.1 regression)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1882: unittest_msgq_insert_all_sort: Begin insert of 86 messages into destq with 199999 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1890: unittest_msgq_insert_all_sort: Done: took 9729us, 0.0486us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1921: unittest_msgq_insert_all_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1945: unittest_msgq_insert_each_sort: Testing msgq insert (each) efficiency: issue #2450 (v1.2.1 regression)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 199999 messages
[<MAIN>                      /  7.152s] Too many tests running (5 >= 5): postponing 0105_transactions_mock start...
[0104_fetch_from_follower_mock/  0.000s] ================= Running test 0104_fetch_from_follower_mock =================
[0104_fetch_from_follower_mock/  0.000s] ==== Stats written to file stats_0104_fetch_from_follower_mock_6229090193646402079.json ====
[0104_fetch_from_follower_mock/  0.000s] [ Test FFF auto.offset.reset=earliest ]
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9611us, 4805.5000us/msg
[0104_fetch_from_follower_mock/  0.002s] Test config file test.conf not found
[0104_fetch_from_follower_mock/  0.003s] Created    kafka instance 0104_fetch_from_follower_mock#producer-52
[0104_fetch_from_follower_mock/  0.003s] Test config file test.conf not found
[0104_fetch_from_follower_mock/  0.003s] Produce to test [0]: messages #0..1000
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 5 messages into destq with 200001 messages
[0104_fetch_from_follower_mock/  0.011s] SUM(POLL): duration 0.008ms
[0104_fetch_from_follower_mock/  0.011s] PRODUCE: duration 7.610ms
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9847us, 1969.4000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 4 messages into destq with 200006 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9632us, 2408.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 200010 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9399us, 4699.5000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 3 messages into destq with 200012 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9400us, 3133.3333us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 61 messages into destq with 200015 messages
[0104_fetch_from_follower_mock/  0.061s] PRODUCE.DELIVERY.WAIT: duration 50.800ms
[0104_fetch_from_follower_mock/  0.063s] Test config file test.conf not found
[0104_fetch_from_follower_mock/  0.064s] Created    kafka instance 0104_fetch_from_follower_mock#consumer-53
[0104_fetch_from_follower_mock/  0.064s] ASSIGN.PARTITIONS: duration 0.102ms
[0104_fetch_from_follower_mock/  0.064s] earliest: assigned 1 partition(s)
[0104_fetch_from_follower_mock/  0.064s] earliest: consume 1000 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 10207us, 167.3279us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 200076 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 10511us, 5255.5000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 200078 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9606us, 4803.0000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 2 messages into destq with 200080 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9541us, 4770.5000us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1982: unittest_msgq_insert_each_sort: Begin insert of 3 messages into destq with 200082 messages
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:1992: unittest_msgq_insert_each_sort: Done: took 9343us, 3114.3333us/msg
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2017: unittest_msgq_insert_each_sort: Total: 1129.0349us/msg over 86 messages in 97097us
RDUT: WARN: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2025: unittest_msgq_insert_each_sort: maximum us/msg exceeded: 1129.0349 > 1.5000 us/msg
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msg.c:2032: unittest_msgq_insert_each_sort
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: msg: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdmurmur2.c:158: unittest_murmur2
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: murmurhash: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdfnv1a.c:111: unittest_fnv1a
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: fnv1a: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:468: ut_high_sigfig
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:500: ut_quantile
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:519: ut_mean
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:541: ut_stddev
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:560: ut_totalcount
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:579: ut_max
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:597: ut_min
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:617: ut_reset
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:631: ut_nan
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:646: ut_sigfigs
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:662: ut_minmax_trackable
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:672: ut_unitmagnitude_overflow
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdhdrhistogram.c:705: ut_subbucketmask_overflow
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: rdhdrhistogram: PASS
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_conf.c:3920: unittest_conf: Safified client.software.name="aba.-va"
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_conf.c:3928: unittest_conf: Safified client.software.version="1.2.3.4.5----a"
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_conf.c:3932: unittest_conf
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: conf: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_broker.c:1849: rd_ut_reconnect_backoff
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: broker: PASS
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4196: unittest_idempotent_producer: Verifying idempotent producer error handling
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4369: unittest_idempotent_producer: Got DeliveryReport event with 3 message(s)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4369: unittest_idempotent_producer: Got DeliveryReport event with 3 message(s)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4369: unittest_idempotent_producer: Got DeliveryReport event with 3 message(s)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4369: unittest_idempotent_producer: Got DeliveryReport event with 3 message(s)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4374: unittest_idempotent_producer:  DR for message: Success: (persistence=2)
[0095_all_brokers_down       /  3.005s] Error: Local: Broker transport failure: 127.0.0.1:2/bootstrap: Connect to ipv4#127.0.0.1:2 failed: Connection refused (after 1ms in state CONNECT)
[0095_all_brokers_down       /  3.005s] Error: Local: All broker connections are down: 2/2 brokers are down
[0084_destroy_flags_local    /  4.031s] Calling rd_kafka_destroy_flags(0x8)
[0084_destroy_flags_local    /  4.032s] rd_kafka_destroy_flags(0x8): duration 0.697ms
[0084_destroy_flags_local    /  4.032s] [ test destroy_flags 0x8 for client_type 1, produce_cnt 0, subscribe 0, unsubscribe 0, local mode: PASS ]
[0084_destroy_flags_local    /  4.032s] 0084_destroy_flags_local: duration 4032.106ms
[0084_destroy_flags_local    /  4.032s] ================= Test 0084_destroy_flags_local PASSED =================
[<MAIN>                      /  7.655s] Too many tests running (5 >= 5): postponing 0106_cgrp_sess_timeout start...
[0105_transactions_mock      /  0.000s] ================= Running test 0105_transactions_mock =================
[0105_transactions_mock      /  0.000s] ==== Stats written to file stats_0105_transactions_mock_8569981069397771540.json ====
[0105_transactions_mock      /  0.000s] Test config file test.conf not found
[0105_transactions_mock      /  0.000s] [ do_test_txn_recoverable_errors ]
[0105_transactions_mock      /  0.000s] Test config file test.conf not found
%5|1594295289.302|MOCK|0105_transactions_mock#producer-55| [thrd:app]: Mock cluster enabled: original bootstrap.servers and security.protocol ignored and replaced
[0105_transactions_mock      /  0.018s] Created    kafka instance 0105_transactions_mock#producer-55
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_request.c:4398: unittest_idempotent_producer
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: request: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1559: do_unittest_config_no_principal_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1587: do_unittest_config_empty_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1659: do_unittest_config_empty_value_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1701: do_unittest_config_value_with_quote_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1616: do_unittest_config_unrecognized_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1445: do_unittest_config_defaults
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1487: do_unittest_config_explicit_scope_and_life
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1530: do_unittest_config_all_explicit_values
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1740: do_unittest_config_extensions
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1764: do_unittest_illegal_extension_keys_should_fail
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_oauthbearer.c:1796: do_unittest_odd_extension_size_should_fail
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: sasl_oauthbearer: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_msgset_reader.c:1713: unittest_aborted_txns
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: aborted_txns: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_cgrp.c:3794: unittest_consumer_group_metadata
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: cgrp: PASS
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_scram.c:943: unittest_scram_nonce
RDUT: PASS: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdkafka_sasl_scram.c:983: unittest_scram_safe
RDUT: INFO: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/src/rdunittest.c:504: rd_unittest: unittest: scram: PASS
[0000_unittests              /  8.329s] 0000_unittests: duration 8328.684ms
[0000_unittests              /  8.329s] ================= Test 0000_unittests PASSED =================
[<MAIN>                      /  8.430s] 5 test(s) running: 0095_all_brokers_down 0103_transactions_local 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      /  0.000s] ================= Running test 0106_cgrp_sess_timeout =================
[0106_cgrp_sess_timeout      /  0.000s] ==== Stats written to file stats_0106_cgrp_sess_timeout_7402446874341362660.json ====
[0106_cgrp_sess_timeout      /  0.000s] [ Test session timeout with sync commit ]
[0095_all_brokers_down       /  4.027s] 0095_all_brokers_down: duration 4026.518ms
[0095_all_brokers_down       /  4.027s] ================= Test 0095_all_brokers_down PASSED =================
[0106_cgrp_sess_timeout      /  0.025s] Test config file test.conf not found
[0106_cgrp_sess_timeout      /  0.026s] Created    kafka instance 0106_cgrp_sess_timeout#producer-57
[0106_cgrp_sess_timeout      /  0.026s] Test config file test.conf not found
[0106_cgrp_sess_timeout      /  0.026s] Produce to test [0]: messages #0..100
[0106_cgrp_sess_timeout      /  0.026s] SUM(POLL): duration 0.001ms
[0106_cgrp_sess_timeout      /  0.026s] PRODUCE: duration 0.274ms
[0106_cgrp_sess_timeout      /  0.031s] PRODUCE.DELIVERY.WAIT: duration 4.588ms
[0106_cgrp_sess_timeout      /  0.031s] Test config file test.conf not found
[0106_cgrp_sess_timeout      /  0.031s] Setting test timeout to 30s * 2.7
[0106_cgrp_sess_timeout      /  0.032s] Created    kafka instance 0106_cgrp_sess_timeout#consumer-58
[0106_cgrp_sess_timeout      /  0.032s] Waiting for initial assignment (_ASSIGN_PARTITIONS) for 7s
[0105_transactions_mock      /  1.528s] rd_kafka_init_transactions(rk, 5000): duration 1510.060ms
RDUT: CCOV: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/tests/0105-transactions_mock.c:139: do_test_txn_recoverable_errors: Code coverage nr 0: PASS (3 code path execution(s))
RDUT: CCOV: /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/tests/0105-transactions_mock.c:140: do_test_txn_recoverable_errors: Code coverage nr 1: PASS (1 code path execution(s))
[0105_transactions_mock      /  1.529s] rd_kafka_begin_transaction(rk): duration 0.135ms
[<MAIN>                      /  9.430s] 4 test(s) running: 0103_transactions_local 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[0104_fetch_from_follower_mock/  2.691s] CONSUME: duration 2626.494ms
[0104_fetch_from_follower_mock/  2.691s] earliest: consumed 1000/1000 messages (0/1 EOFs)
[0104_fetch_from_follower_mock/  2.691s] Closing consumer
[0104_fetch_from_follower_mock/  2.691s] CONSUMER.CLOSE: duration 0.631ms
[0104_fetch_from_follower_mock/  2.695s] [ Test FFF auto.offset.reset=earliest PASSED ]
[0104_fetch_from_follower_mock/  2.695s] [ Test FFF auto.offset.reset=latest ]
[0104_fetch_from_follower_mock/  2.696s] Test config file test.conf not found
[0104_fetch_from_follower_mock/  2.697s] Created    kafka instance 0104_fetch_from_follower_mock#producer-60
[0104_fetch_from_follower_mock/  2.697s] Test config file test.conf not found
[0104_fetch_from_follower_mock/  2.697s] Produce to test [0]: messages #0..1000
[0104_fetch_from_follower_mock/  2.701s] SUM(POLL): duration 0.001ms
[0104_fetch_from_follower_mock/  2.701s] PRODUCE: duration 3.604ms
[0104_fetch_from_follower_mock/  2.755s] PRODUCE.DELIVERY.WAIT: duration 54.238ms
[0104_fetch_from_follower_mock/  2.757s] Test config file test.conf not found
[0104_fetch_from_follower_mock/  2.758s] Created    kafka instance 0104_fetch_from_follower_mock#consumer-61
[0104_fetch_from_follower_mock/  2.758s] ASSIGN.PARTITIONS: duration 0.107ms
[0104_fetch_from_follower_mock/  2.758s] latest: assigned 1 partition(s)
[0104_fetch_from_follower_mock/  2.758s] latest: not expecting any messages for 5000ms
[<MAIN>                      / 10.430s] 4 test(s) running: 0103_transactions_local 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      /  3.007s] rd_kafka_send_offsets_to_transaction( rk, offsets, cgmetadata, -1): duration 4.588ms
[0105_transactions_mock      /  3.008s] rd_kafka_commit_transaction(rk, 5000): duration 0.537ms
[0105_transactions_mock      /  3.011s] [ do_test_txn_recoverable_errors PASS ]
[0105_transactions_mock      /  3.011s] [ do_test_txn_requires_abort_errors ]
[0105_transactions_mock      /  3.011s] Test config file test.conf not found
%5|1594295292.312|MOCK|0105_transactions_mock#producer-62| [thrd:app]: Mock cluster enabled: original bootstrap.servers and security.protocol ignored and replaced
[0105_transactions_mock      /  3.013s] Created    kafka instance 0105_transactions_mock#producer-62
[0105_transactions_mock      /  3.018s] rd_kafka_init_transactions(rk, 5000): duration 4.282ms
[0105_transactions_mock      /  3.018s] rd_kafka_begin_transaction(rk): duration 0.108ms
[0105_transactions_mock      /  3.018s] 1. Fail on produce
[0105_transactions_mock      /  3.018s] 0105_transactions_mock#producer-62: Flushing 1 messages
[<MAIN>                      / 11.430s] 4 test(s) running: 0103_transactions_local 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
%3|1594295293.317|TXNERR|0105_transactions_mock#producer-62| [thrd:127.0.0.1:53531/bootstrap]: Current transaction failed: ProduceRequest for mytopic [1] with 1 message(s) failed: Broker: Topic authorization failed (broker 1 PID{Id:321632000,Epoch:0}, base seq 0): current transaction must be aborted (TOPIC_AUTHORIZATION_FAILED)
[0105_transactions_mock      /  4.017s] FLUSH: duration 999.204ms
[0105_transactions_mock      /  4.017s] Error _STATE: Operation not valid in state AbortableError
[0105_transactions_mock      /  4.018s] rd_kafka_abort_transaction(rk, -1): duration 0.601ms
[0105_transactions_mock      /  4.018s] 2. Fail on AddPartitionsToTxn
[0105_transactions_mock      /  4.018s] rd_kafka_begin_transaction(rk): duration 0.124ms
%3|1594295293.320|ADDPARTS|0105_transactions_mock#producer-62| [thrd:main]: TxnCoordinator/1: Failed to add partition "mytopic" [0] to transaction: Broker: Topic authorization failed
%3|1594295293.320|TXNERR|0105_transactions_mock#producer-62| [thrd:main]: Current transaction failed: Failed to add 1/1 partition(s) to transaction on broker TxnCoordinator/1: Broker: Topic authorization failed (after 0 ms) (TOPIC_AUTHORIZATION_FAILED)
[0105_transactions_mock      /  4.020s] commit_transaction() error _STATE: Operation not valid in state AbortableError
[0105_transactions_mock      /  4.020s] rd_kafka_abort_transaction(rk, -1): duration 0.279ms
[0105_transactions_mock      /  4.020s] 3. Fail on AddOffsetsToTxn
[0105_transactions_mock      /  4.020s] rd_kafka_begin_transaction(rk): duration 0.095ms
%3|1594295293.321|ADDOFFSETS|0105_transactions_mock#producer-62| [thrd:main]: TxnCoordinator/1: Failed to add offsets to transaction: Broker: Group authorization failed
%3|1594295293.321|TXNERR|0105_transactions_mock#producer-62| [thrd:main]: Current transaction failed: Failed to add offsets to transaction on broker TxnCoordinator/1: Broker: Group authorization failed (after 0ms) (GROUP_AUTHORIZATION_FAILED)
[0105_transactions_mock      /  4.022s] rd_kafka_abort_transaction(rk, -1): duration 0.434ms
[0105_transactions_mock      /  4.024s] [ do_test_txn_requires_abort_errors PASS ]
[0105_transactions_mock      /  4.024s] [ Test coordinator down ]
[0105_transactions_mock      /  4.025s] Test config file test.conf not found
%5|1594295293.326|MOCK|0105_transactions_mock#producer-63| [thrd:app]: Mock cluster enabled: original bootstrap.servers and security.protocol ignored and replaced
[0105_transactions_mock      /  4.027s] Created    kafka instance 0105_transactions_mock#producer-63
[0105_transactions_mock      /  4.027s] Starting transaction
[0105_transactions_mock      /  4.032s] rd_kafka_init_transactions(rk, 5000): duration 4.591ms
[0105_transactions_mock      /  4.032s] rd_kafka_begin_transaction(rk): duration 0.103ms
[0105_transactions_mock      /  4.032s] Test config file test.conf not found
[0105_transactions_mock      /  4.032s] Produce to test [-1]: messages #0..500
[0105_transactions_mock      /  4.034s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      /  4.034s] PRODUCE: duration 1.734ms
[0105_transactions_mock      /  4.034s] Bringing down coordinator 1
[0105_transactions_mock      /  4.034s] Ignoring allowed error: _TRANSPORT: TxnCoordinator: Disconnected (after 3ms in state UP)
[0105_transactions_mock      /  4.034s] 0105_transactions_mock#producer-63 rdkafka error (non-testfatal): Local: Broker transport failure: TxnCoordinator: Disconnected (after 3ms in state UP)
[0105_transactions_mock      /  4.034s] Ignoring allowed error: _TRANSPORT: 127.0.0.1:43733/1: Disconnected (after 5ms in state UP)
[0105_transactions_mock      /  4.034s] 0105_transactions_mock#producer-63 rdkafka error (non-testfatal): Local: Broker transport failure: 127.0.0.1:43733/1: Disconnected (after 5ms in state UP)
[<MAIN>                      / 12.431s] 4 test(s) running: 0103_transactions_local 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      /  4.034s] Rebalance #1: _ASSIGN_PARTITIONS: 4 partition(s)
[0106_cgrp_sess_timeout      /  4.034s] ASSIGN.PARTITIONS: duration 0.191ms
[0106_cgrp_sess_timeout      /  4.034s] assign: assigned 4 partition(s)
[<MAIN>                      / 13.431s] 4 test(s) running: 0103_transactions_local 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      /  5.037s] consume: consume 10 messages
[0106_cgrp_sess_timeout      /  5.037s] CONSUME: duration 0.026ms
[0106_cgrp_sess_timeout      /  5.037s] consume: consumed 10/10 messages (0/-1 EOFs)
[0106_cgrp_sess_timeout      /  5.037s] Waiting for session timeout revoke (_REVOKE_PARTITIONS) for 9s
[0103_transactions_local     /  7.026s] init_transactions(): duration 7000.120ms
[0103_transactions_local     /  7.026s] init_transactions() failed as expected: Failed to initialize Producer ID: Local: Timed out
[0103_transactions_local     /  7.027s] 0103_transactions_local: duration 7026.563ms
[0103_transactions_local     /  7.027s] ================= Test 0103_transactions_local PASSED =================
[<MAIN>                      / 14.431s] 3 test(s) running: 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      /  7.034s] Test config file test.conf not found
[0105_transactions_mock      /  7.034s] Produce to test [-1]: messages #500..1000
[0105_transactions_mock      /  7.035s] SUM(POLL): duration 0.000ms
[0105_transactions_mock      /  7.035s] PRODUCE: duration 0.621ms
[0104_fetch_from_follower_mock/  7.758s] CONSUME: duration 5000.131ms
[0104_fetch_from_follower_mock/  7.758s] test_consumer_poll_no_msgs:3572: latest: Verifying 0 received messages (flags 0xf): expecting msgids 0..0 (0)
[0104_fetch_from_follower_mock/  7.758s] test_consumer_poll_no_msgs:3572: latest: Verification of 0 received messages succeeded: expected msgids 0..0 (0)
[0104_fetch_from_follower_mock/  7.758s] Closing consumer
[0104_fetch_from_follower_mock/  7.758s] CONSUMER.CLOSE: duration 0.094ms
[0104_fetch_from_follower_mock/  7.762s] [ Test FFF auto.offset.reset=latest PASSED ]
[0104_fetch_from_follower_mock/  7.762s] [ Test lagging FFF offset reset ]
[0104_fetch_from_follower_mock/  7.762s] Test config file test.conf not found
[0104_fetch_from_follower_mock/  7.763s] Created    kafka instance 0104_fetch_from_follower_mock#producer-65
[0104_fetch_from_follower_mock/  7.763s] Test config file test.conf not found
[0104_fetch_from_follower_mock/  7.763s] Produce to test [0]: messages #0..10
[0104_fetch_from_follower_mock/  7.763s] SUM(POLL): duration 0.000ms
[0104_fetch_from_follower_mock/  7.763s] PRODUCE: duration 0.026ms
[0104_fetch_from_follower_mock/  7.766s] PRODUCE.DELIVERY.WAIT: duration 2.539ms
[0104_fetch_from_follower_mock/  7.766s] Test config file test.conf not found
[0104_fetch_from_follower_mock/  7.767s] Created    kafka instance 0104_fetch_from_follower_mock#consumer-66
[0104_fetch_from_follower_mock/  7.767s] ASSIGN.PARTITIONS: duration 0.041ms
[0104_fetch_from_follower_mock/  7.767s] lag: assigned 1 partition(s)
[0104_fetch_from_follower_mock/  7.767s] up to wmark: consume 7 messages
[<MAIN>                      / 15.431s] 3 test(s) running: 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[<MAIN>                      / 16.432s] 3 test(s) running: 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      /  9.035s] Bringing up coordinator 1
[0104_fetch_from_follower_mock/  9.770s] CONSUME: duration 2003.314ms
[0104_fetch_from_follower_mock/  9.770s] up to wmark: consumed 7/7 messages (0/0 EOFs)
[0104_fetch_from_follower_mock/  9.770s] no msgs: not expecting any messages for 3000ms
[<MAIN>                      / 17.432s] 3 test(s) running: 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[<MAIN>                      / 18.432s] 3 test(s) running: 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[<MAIN>                      / 19.432s] 3 test(s) running: 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 11.799s] rd_kafka_commit_transaction(rk, -1): duration 2763.146ms
[0105_transactions_mock      / 11.801s] [ Test coordinator down: PASS ]
[0105_transactions_mock      / 11.801s] [ Test leader down ]
[0105_transactions_mock      / 11.802s] Test config file test.conf not found
%5|1594295301.103|MOCK|0105_transactions_mock#producer-67| [thrd:app]: Mock cluster enabled: original bootstrap.servers and security.protocol ignored and replaced
[0105_transactions_mock      / 11.804s] Created    kafka instance 0105_transactions_mock#producer-67
[0105_transactions_mock      / 11.804s] Starting transaction
[0105_transactions_mock      / 11.809s] rd_kafka_init_transactions(rk, 5000): duration 4.887ms
[0105_transactions_mock      / 11.809s] rd_kafka_begin_transaction(rk): duration 0.131ms
[0105_transactions_mock      / 11.809s] Test config file test.conf not found
[0105_transactions_mock      / 11.809s] Produce to test [-1]: messages #0..500
%4|1594295301.109|SESSTMOUT|0106_cgrp_sess_timeout#consumer-58| [thrd:main]: Consumer group session timed out (in join-state started) after 6000 ms without a successful response from the group coordinator (broker 1, last error was Broker: Not coordinator): revoking assignment and rejoining group
[0105_transactions_mock      / 11.811s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 11.811s] PRODUCE: duration 1.498ms
[0105_transactions_mock      / 11.811s] Bringing down leader 2
[0106_cgrp_sess_timeout      / 11.037s] Rebalance #2: _REVOKE_PARTITIONS: 4 partition(s)
[0106_cgrp_sess_timeout      / 11.038s] Performing sync commit
[0104_fetch_from_follower_mock/ 12.770s] CONSUME: duration 3000.108ms
[0104_fetch_from_follower_mock/ 12.770s] test_consumer_poll_no_msgs:3572: no msgs: Verifying 0 received messages (flags 0xf): expecting msgids 0..0 (0)
[0104_fetch_from_follower_mock/ 12.770s] test_consumer_poll_no_msgs:3572: no msgs: Verification of 0 received messages succeeded: expected msgids 0..0 (0)
[0104_fetch_from_follower_mock/ 12.771s] remaining: consume 3 messages
[0104_fetch_from_follower_mock/ 12.774s] CONSUME: duration 3.768ms
[0104_fetch_from_follower_mock/ 12.774s] remaining: consumed 3/3 messages (0/1 EOFs)
[0104_fetch_from_follower_mock/ 12.774s] Closing consumer
[0104_fetch_from_follower_mock/ 12.775s] CONSUMER.CLOSE: duration 0.712ms
[0104_fetch_from_follower_mock/ 12.780s] [ Test lagging FFF offset reset PASSED ]
[0104_fetch_from_follower_mock/ 12.780s] [ Test unknown follower ]
[0104_fetch_from_follower_mock/ 12.781s] Test config file test.conf not found
[0104_fetch_from_follower_mock/ 12.782s] Created    kafka instance 0104_fetch_from_follower_mock#producer-69
[0104_fetch_from_follower_mock/ 12.782s] Test config file test.conf not found
[0104_fetch_from_follower_mock/ 12.782s] Produce to test [0]: messages #0..1000
[0104_fetch_from_follower_mock/ 12.786s] SUM(POLL): duration 0.000ms
[0104_fetch_from_follower_mock/ 12.786s] PRODUCE: duration 3.486ms
[0104_fetch_from_follower_mock/ 12.838s] PRODUCE.DELIVERY.WAIT: duration 52.216ms
[0104_fetch_from_follower_mock/ 12.839s] Test config file test.conf not found
[0104_fetch_from_follower_mock/ 12.841s] Created    kafka instance 0104_fetch_from_follower_mock#consumer-70
[0104_fetch_from_follower_mock/ 12.841s] ASSIGN.PARTITIONS: duration 0.114ms
[0104_fetch_from_follower_mock/ 12.841s] unknown follower: assigned 1 partition(s)
[0104_fetch_from_follower_mock/ 12.841s] unknown follower: not expecting any messages for 5000ms
[<MAIN>                      / 20.433s] 3 test(s) running: 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      / 12.240s] UNASSIGN.PARTITIONS: duration 0.137ms
[0106_cgrp_sess_timeout      / 12.240s] unassign: unassigned current partitions
[0106_cgrp_sess_timeout      / 12.240s] Waiting for second assignment (_ASSIGN_PARTITIONS) for 7s
[<MAIN>                      / 21.433s] 3 test(s) running: 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
%5|1594295303.637|FETCH|0104_fetch_from_follower_mock#consumer-70| [thrd:127.0.0.1:53903/bootstrap]: 127.0.0.1:53903/1: test [0]: preferred replica (19) is unknown: refreshing metadata
[<MAIN>                      / 22.433s] 3 test(s) running: 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 14.812s] Test config file test.conf not found
[0105_transactions_mock      / 14.812s] Produce to test [-1]: messages #500..1000
[0105_transactions_mock      / 14.830s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 14.830s] PRODUCE: duration 17.833ms
%5|1594295304.644|FETCH|0104_fetch_from_follower_mock#consumer-70| [thrd:127.0.0.1:53903/bootstrap]: 127.0.0.1:53903/1: test [0]: preferred replica (19) lease changing too quickly (1s < 60s): possibly due to unavailable replica or stale cluster state: backing off next fetch
[<MAIN>                      / 23.433s] 3 test(s) running: 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[<MAIN>                      / 24.434s] 3 test(s) running: 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 16.830s] Bringing up leader 2
[0105_transactions_mock      / 17.157s] rd_kafka_commit_transaction(rk, -1): duration 327.309ms
[0105_transactions_mock      / 17.160s] [ Test leader down: PASS ]
[0105_transactions_mock      / 17.160s] [ do_test_txns_not_supported ]
[0105_transactions_mock      / 17.160s] Test config file test.conf not found
[0105_transactions_mock      / 17.160s] Setting test timeout to 10s * 2.7
[0105_transactions_mock      / 17.160s] Created    kafka instance 0105_transactions_mock#producer-71
%1|1594295306.465|TXNERR|0105_transactions_mock#producer-71| [thrd:main]: Fatal transaction error: Transactions not supported by any of the 1 connected broker(s): requires Apache Kafka broker version >= 0.11.0 (_UNSUPPORTED_FEATURE)
%0|1594295306.465|FATAL|0105_transactions_mock#producer-71| [thrd:main]: Fatal error: Local: Required feature not supported by broker: Transactions not supported by any of the 1 connected broker(s): requires Apache Kafka broker version >= 0.11.0
[0105_transactions_mock      / 17.165s] init_transactions() returned _UNSUPPORTED_FEATURE: Transactions not supported by any of the 1 connected broker(s): requires Apache Kafka broker version >= 0.11.0
[0105_transactions_mock      / 17.167s] [ do_test_txns_not_supported: PASS ]
[0105_transactions_mock      / 17.167s] [ do_test_txns_send_offsets_concurrent_is_retriable ]
[0105_transactions_mock      / 17.167s] Test config file test.conf not found
%5|1594295306.468|MOCK|0105_transactions_mock#producer-72| [thrd:app]: Mock cluster enabled: original bootstrap.servers and security.protocol ignored and replaced
[0105_transactions_mock      / 17.169s] Created    kafka instance 0105_transactions_mock#producer-72
[0105_transactions_mock      / 17.172s] rd_kafka_init_transactions(rk, 5000): duration 2.588ms
[0105_transactions_mock      / 17.172s] rd_kafka_begin_transaction(rk): duration 0.097ms
[0105_transactions_mock      / 17.172s] 0105_transactions_mock#producer-72: Flushing 1 messages
[0104_fetch_from_follower_mock/ 17.841s] CONSUME: duration 5000.076ms
[0104_fetch_from_follower_mock/ 17.841s] test_consumer_poll_no_msgs:3572: unknown follower: Verifying 0 received messages (flags 0xf): expecting msgids 0..0 (0)
[0104_fetch_from_follower_mock/ 17.841s] test_consumer_poll_no_msgs:3572: unknown follower: Verification of 0 received messages succeeded: expected msgids 0..0 (0)
[0104_fetch_from_follower_mock/ 17.841s] proper follower: consume 1000 messages
[<MAIN>                      / 25.434s] 3 test(s) running: 0104_fetch_from_follower_mock 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      / 17.038s] Rebalance #3: _ASSIGN_PARTITIONS: 4 partition(s)
[0106_cgrp_sess_timeout      / 17.038s] ASSIGN.PARTITIONS: duration 0.108ms
[0106_cgrp_sess_timeout      / 17.038s] assign: assigned 4 partition(s)
[0104_fetch_from_follower_mock/ 18.376s] CONSUME: duration 534.507ms
[0104_fetch_from_follower_mock/ 18.376s] proper follower: consumed 1000/1000 messages (0/1 EOFs)
[0104_fetch_from_follower_mock/ 18.376s] Closing consumer
[0104_fetch_from_follower_mock/ 18.376s] CONSUMER.CLOSE: duration 0.621ms
[0104_fetch_from_follower_mock/ 18.380s] [ Test unknown follower PASSED ]
[0104_fetch_from_follower_mock/ 18.380s] 0104_fetch_from_follower_mock: duration 18380.105ms
[0104_fetch_from_follower_mock/ 18.380s] ================= Test 0104_fetch_from_follower_mock PASSED =================
[0105_transactions_mock      / 18.171s] FLUSH: duration 999.016ms
[0105_transactions_mock      / 18.474s] Error CONCURRENT_TRANSACTIONS: Failed to add offsets to transaction on broker TxnCoordinator/1: Broker: Producer attempted to update a transaction while another concurrent operation on the same transaction was ongoing (after 0ms)
[0105_transactions_mock      / 18.477s] rd_kafka_send_offsets_to_transaction(rk, offsets, cgmetadata, -1): duration 3.009ms
[0105_transactions_mock      / 18.477s] rd_kafka_commit_transaction(rk, 5000): duration 0.478ms
[0105_transactions_mock      / 18.480s] [ do_test_txns_send_offsets_concurrent_is_retriable PASS ]
[0105_transactions_mock      / 18.480s] [ do_test_txns_no_timeout_crash ]
[0105_transactions_mock      / 18.480s] Test config file test.conf not found
%5|1594295307.781|MOCK|0105_transactions_mock#producer-73| [thrd:app]: Mock cluster enabled: original bootstrap.servers and security.protocol ignored and replaced
[0105_transactions_mock      / 18.482s] Created    kafka instance 0105_transactions_mock#producer-73
[0105_transactions_mock      / 18.487s] rd_kafka_init_transactions(rk, 5000): duration 4.487ms
[0105_transactions_mock      / 18.487s] rd_kafka_begin_transaction(rk): duration 0.112ms
[0105_transactions_mock      / 18.487s] 0105_transactions_mock#producer-73: Flushing 1 messages
[<MAIN>                      / 26.434s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      / 18.039s] Closing consumer
[0106_cgrp_sess_timeout      / 18.039s] Rebalance #4: _REVOKE_PARTITIONS: 4 partition(s)
[0106_cgrp_sess_timeout      / 18.039s] Performing sync commit
[0105_transactions_mock      / 19.484s] FLUSH: duration 996.962ms
[<MAIN>                      / 27.434s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      / 19.040s] UNASSIGN.PARTITIONS: duration 0.078ms
[0106_cgrp_sess_timeout      / 19.040s] unassign: unassigned current partitions
[0106_cgrp_sess_timeout      / 19.041s] CONSUMER.CLOSE: duration 1001.451ms
[0106_cgrp_sess_timeout      / 19.044s] [ Test session timeout with sync commit PASSED ]
[0106_cgrp_sess_timeout      / 19.044s] [ Test session timeout with async commit ]
[0106_cgrp_sess_timeout      / 19.045s] Test config file test.conf not found
[0106_cgrp_sess_timeout      / 19.046s] Created    kafka instance 0106_cgrp_sess_timeout#producer-75
[0106_cgrp_sess_timeout      / 19.046s] Test config file test.conf not found
[0106_cgrp_sess_timeout      / 19.046s] Produce to test [0]: messages #0..100
[0106_cgrp_sess_timeout      / 19.046s] SUM(POLL): duration 0.001ms
[0106_cgrp_sess_timeout      / 19.046s] PRODUCE: duration 0.249ms
[0106_cgrp_sess_timeout      / 19.052s] PRODUCE.DELIVERY.WAIT: duration 5.179ms
[0106_cgrp_sess_timeout      / 19.053s] Test config file test.conf not found
[0106_cgrp_sess_timeout      / 19.053s] Setting test timeout to 30s * 2.7
[0106_cgrp_sess_timeout      / 19.054s] Created    kafka instance 0106_cgrp_sess_timeout#consumer-76
[0106_cgrp_sess_timeout      / 19.054s] Waiting for initial assignment (_ASSIGN_PARTITIONS) for 7s
%5|1594295309.788|REQTMOUT|0105_transactions_mock#producer-73| [thrd:TxnCoordinator]: TxnCoordinator/1: Timed out AddOffsetsToTxnRequest in flight (after 1003ms, timeout #0)
%4|1594295309.788|REQTMOUT|0105_transactions_mock#producer-73| [thrd:TxnCoordinator]: TxnCoordinator/1: Timed out 1 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
[<MAIN>                      / 28.435s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
%5|1594295310.791|REQTMOUT|0105_transactions_mock#producer-73| [thrd:TxnCoordinator]: TxnCoordinator/1: Timed out ApiVersionRequest in flight (after 1000ms, timeout #0)
%4|1594295310.791|REQTMOUT|0105_transactions_mock#producer-73| [thrd:TxnCoordinator]: TxnCoordinator/1: Timed out 1 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
[<MAIN>                      / 29.435s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
%5|1594295311.788|REQTMOUT|0105_transactions_mock#producer-73| [thrd:127.0.0.1:48517/bootstrap]: 127.0.0.1:48517/3: Timed out MetadataRequest in flight (after 1999ms, timeout #0)
%5|1594295311.788|REQTMOUT|0105_transactions_mock#producer-73| [thrd:127.0.0.1:48517/bootstrap]: 127.0.0.1:48517/3: Timed out FindCoordinatorRequest in flight (after 1499ms, timeout #1)
%4|1594295311.788|REQTMOUT|0105_transactions_mock#producer-73| [thrd:127.0.0.1:48517/bootstrap]: 127.0.0.1:48517/3: Timed out 2 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
[<MAIN>                      / 30.435s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
%5|1594295312.791|REQTMOUT|0105_transactions_mock#producer-73| [thrd:127.0.0.1:53949/bootstrap]: 127.0.0.1:53949/2: Timed out ApiVersionRequest in flight (after 1001ms, timeout #0)
%4|1594295312.791|REQTMOUT|0105_transactions_mock#producer-73| [thrd:127.0.0.1:53949/bootstrap]: 127.0.0.1:53949/2: Timed out 1 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
%4|1594295312.900|REQTMOUT|0105_transactions_mock#producer-73| [thrd:TxnCoordinator]: TxnCoordinator: Timed out 0 in-flight, 0 retry-queued, 1 out-queue, 0 partially-sent requests
[<MAIN>                      / 31.435s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      / 23.055s] Rebalance #1: _ASSIGN_PARTITIONS: 4 partition(s)
[0106_cgrp_sess_timeout      / 23.055s] ASSIGN.PARTITIONS: duration 0.247ms
[0106_cgrp_sess_timeout      / 23.055s] assign: assigned 4 partition(s)
%5|1594295313.291|REQTMOUT|0105_transactions_mock#producer-73| [thrd:127.0.0.1:48449/bootstrap]: 127.0.0.1:48449/1: Timed out ApiVersionRequest in flight (after 1001ms, timeout #0)
%4|1594295313.291|REQTMOUT|0105_transactions_mock#producer-73| [thrd:127.0.0.1:48449/bootstrap]: 127.0.0.1:48449/1: Timed out 1 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
[0105_transactions_mock      / 24.485s] send_offsets..() failed with retriable error: Transactional operation timed out
[0105_transactions_mock      / 24.485s] Retrying send_offsets..()
%5|1594295313.791|REQTMOUT|0105_transactions_mock#producer-73| [thrd:127.0.0.1:48517/bootstrap]: 127.0.0.1:48517/3: Timed out ApiVersionRequest in flight (after 1001ms, timeout #0)
%4|1594295313.791|REQTMOUT|0105_transactions_mock#producer-73| [thrd:127.0.0.1:48517/bootstrap]: 127.0.0.1:48517/3: Timed out 1 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
%5|1594295313.974|REQTMOUT|0105_transactions_mock#producer-73| [thrd:127.0.0.1:53949/bootstrap]: 127.0.0.1:53949/2: Timed out ApiVersionRequest in flight (after 1001ms, timeout #0)
%4|1594295313.974|REQTMOUT|0105_transactions_mock#producer-73| [thrd:127.0.0.1:53949/bootstrap]: 127.0.0.1:53949/2: Timed out 1 in-flight, 0 retry-queued, 0 out-queue, 0 partially-sent requests
[<MAIN>                      / 32.436s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      / 24.056s] consume: consume 10 messages
[0106_cgrp_sess_timeout      / 24.056s] CONSUME: duration 0.025ms
[0106_cgrp_sess_timeout      / 24.056s] consume: consumed 10/10 messages (0/-1 EOFs)
[0106_cgrp_sess_timeout      / 24.057s] Waiting for session timeout revoke (_REVOKE_PARTITIONS) for 9s
%3|1594295314.289|ADDOFFSETS|0105_transactions_mock#producer-73| [thrd:main]: TxnCoordinator/1: Failed to add offsets to transaction: Local: Outdated
[0105_transactions_mock      / 25.095s] [ do_test_txns_no_timeout_crash PASS ]
[0105_transactions_mock      / 25.095s] Setting test timeout to 200s * 2.7
[0105_transactions_mock      / 25.095s] [ Test switching coordinators ]
[0105_transactions_mock      / 25.095s] Test config file test.conf not found
%5|1594295314.396|MOCK|0105_transactions_mock#producer-77| [thrd:app]: Mock cluster enabled: original bootstrap.servers and security.protocol ignored and replaced
[0105_transactions_mock      / 25.097s] Created    kafka instance 0105_transactions_mock#producer-77
[0105_transactions_mock      / 25.097s] Starting transaction
[0105_transactions_mock      / 25.101s] rd_kafka_init_transactions(rk, 5000): duration 4.620ms
[0105_transactions_mock      / 25.101s] Changing transaction coordinator from 1 to 2
[0105_transactions_mock      / 25.101s] rd_kafka_begin_transaction(rk): duration 0.122ms
[0105_transactions_mock      / 25.101s] Test config file test.conf not found
[0105_transactions_mock      / 25.102s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 25.102s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 25.102s] PRODUCE: duration 0.076ms
[<MAIN>                      / 33.436s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 26.115s] PRODUCE.DELIVERY.WAIT: duration 1013.051ms
[0105_transactions_mock      / 26.115s] Changing transaction coordinator from 2 to 3
[0105_transactions_mock      / 26.115s] Test config file test.conf not found
[0105_transactions_mock      / 26.115s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 26.116s] SUM(POLL): duration 0.000ms
[0105_transactions_mock      / 26.116s] PRODUCE: duration 0.592ms
[0105_transactions_mock      / 26.116s] Changing transaction coordinator from 3 to 4
[0105_transactions_mock      / 26.117s] rd_kafka_commit_transaction(rk, -1): duration 1.544ms
[0105_transactions_mock      / 26.117s] Changing transaction coordinator from 4 to 5
[0105_transactions_mock      / 26.118s] rd_kafka_begin_transaction(rk): duration 0.116ms
[0105_transactions_mock      / 26.118s] Test config file test.conf not found
[0105_transactions_mock      / 26.118s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 26.118s] SUM(POLL): duration 0.000ms
[0105_transactions_mock      / 26.118s] PRODUCE: duration 0.214ms
[<MAIN>                      / 34.436s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 27.602s] PRODUCE.DELIVERY.WAIT: duration 1483.664ms
[0105_transactions_mock      / 27.602s] Test config file test.conf not found
[0105_transactions_mock      / 27.602s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 27.602s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 27.602s] PRODUCE: duration 0.583ms
[0105_transactions_mock      / 27.602s] Changing transaction coordinator from 5 to 1
[0105_transactions_mock      / 27.603s] rd_kafka_abort_transaction(rk, -1): duration 0.886ms
[0105_transactions_mock      / 27.603s] Changing transaction coordinator from 1 to 2
[0105_transactions_mock      / 27.604s] rd_kafka_begin_transaction(rk): duration 0.142ms
[0105_transactions_mock      / 27.604s] Test config file test.conf not found
[0105_transactions_mock      / 27.604s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 27.604s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 27.604s] PRODUCE: duration 0.203ms
[<MAIN>                      / 35.436s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[<MAIN>                      / 36.436s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 29.105s] PRODUCE.DELIVERY.WAIT: duration 1501.461ms
[0105_transactions_mock      / 29.105s] Test config file test.conf not found
[0105_transactions_mock      / 29.106s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 29.106s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 29.106s] PRODUCE: duration 0.625ms
[0105_transactions_mock      / 29.107s] rd_kafka_abort_transaction(rk, -1): duration 1.110ms
[0105_transactions_mock      / 29.107s] Changing transaction coordinator from 2 to 3
[0105_transactions_mock      / 29.108s] rd_kafka_begin_transaction(rk): duration 0.145ms
[0105_transactions_mock      / 29.108s] Test config file test.conf not found
[0105_transactions_mock      / 29.108s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 29.108s] SUM(POLL): duration 0.000ms
[0105_transactions_mock      / 29.108s] PRODUCE: duration 0.219ms
[<MAIN>                      / 37.437s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 30.602s] PRODUCE.DELIVERY.WAIT: duration 1493.788ms
[0105_transactions_mock      / 30.602s] Changing transaction coordinator from 3 to 4
[0105_transactions_mock      / 30.602s] Test config file test.conf not found
[0105_transactions_mock      / 30.602s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 30.603s] SUM(POLL): duration 0.002ms
[0105_transactions_mock      / 30.603s] PRODUCE: duration 0.593ms
[0105_transactions_mock      / 30.603s] Changing transaction coordinator from 4 to 5
[0105_transactions_mock      / 30.604s] rd_kafka_abort_transaction(rk, -1): duration 1.058ms
[0105_transactions_mock      / 30.604s] Changing transaction coordinator from 5 to 1
[0105_transactions_mock      / 30.604s] rd_kafka_begin_transaction(rk): duration 0.140ms
[0105_transactions_mock      / 30.604s] Test config file test.conf not found
[0105_transactions_mock      / 30.604s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 30.604s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 30.604s] PRODUCE: duration 0.235ms
[<MAIN>                      / 38.437s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
%4|1594295320.131|SESSTMOUT|0106_cgrp_sess_timeout#consumer-76| [thrd:main]: Consumer group session timed out (in join-state started) after 6000 ms without a successful response from the group coordinator (broker 1, last error was Broker: Not coordinator): revoking assignment and rejoining group
[0106_cgrp_sess_timeout      / 30.058s] Rebalance #2: _REVOKE_PARTITIONS: 4 partition(s)
[0106_cgrp_sess_timeout      / 30.058s] Performing async commit
[<MAIN>                      / 39.437s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      / 31.058s] UNASSIGN.PARTITIONS: duration 0.180ms
[0106_cgrp_sess_timeout      / 31.058s] unassign: unassigned current partitions
[0106_cgrp_sess_timeout      / 31.058s] Waiting for second assignment (_ASSIGN_PARTITIONS) for 7s
%4|1594295321.335|COMMITFAIL|0106_cgrp_sess_timeout#consumer-76| [thrd:main]: Offset commit (manual) failed for 4/4 partition(s): Broker: Unknown member: test[0]@17(Broker: Unknown member)
[0105_transactions_mock      / 32.105s] PRODUCE.DELIVERY.WAIT: duration 1500.927ms
[0105_transactions_mock      / 32.106s] Test config file test.conf not found
[0105_transactions_mock      / 32.106s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 32.106s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 32.106s] PRODUCE: duration 0.582ms
[0105_transactions_mock      / 32.107s] rd_kafka_abort_transaction(rk, -1): duration 1.094ms
[0105_transactions_mock      / 32.107s] Changing transaction coordinator from 1 to 2
[0105_transactions_mock      / 32.108s] rd_kafka_begin_transaction(rk): duration 0.135ms
[0105_transactions_mock      / 32.108s] Test config file test.conf not found
[0105_transactions_mock      / 32.108s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 32.108s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 32.108s] PRODUCE: duration 0.219ms
[<MAIN>                      / 40.438s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 33.602s] PRODUCE.DELIVERY.WAIT: duration 1493.668ms
[0105_transactions_mock      / 33.602s] Test config file test.conf not found
[0105_transactions_mock      / 33.602s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 33.602s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 33.602s] PRODUCE: duration 0.609ms
[0105_transactions_mock      / 33.602s] Changing transaction coordinator from 2 to 3
[0105_transactions_mock      / 33.604s] rd_kafka_commit_transaction(rk, -1): duration 1.313ms
[0105_transactions_mock      / 33.604s] Changing transaction coordinator from 3 to 4
[0105_transactions_mock      / 33.604s] rd_kafka_begin_transaction(rk): duration 0.140ms
[0105_transactions_mock      / 33.604s] Test config file test.conf not found
[0105_transactions_mock      / 33.604s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 33.604s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 33.604s] PRODUCE: duration 0.199ms
[<MAIN>                      / 41.438s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[<MAIN>                      / 42.438s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 35.106s] PRODUCE.DELIVERY.WAIT: duration 1501.325ms
[0105_transactions_mock      / 35.106s] Changing transaction coordinator from 4 to 5
[0105_transactions_mock      / 35.106s] Test config file test.conf not found
[0105_transactions_mock      / 35.106s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 35.107s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 35.107s] PRODUCE: duration 0.587ms
[0105_transactions_mock      / 35.108s] rd_kafka_abort_transaction(rk, -1): duration 1.074ms
[0105_transactions_mock      / 35.108s] Changing transaction coordinator from 5 to 1
[0105_transactions_mock      / 35.108s] rd_kafka_begin_transaction(rk): duration 0.131ms
[0105_transactions_mock      / 35.108s] Test config file test.conf not found
[0105_transactions_mock      / 35.108s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 35.108s] SUM(POLL): duration 0.000ms
[0105_transactions_mock      / 35.108s] PRODUCE: duration 0.243ms
[<MAIN>                      / 43.438s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 36.602s] PRODUCE.DELIVERY.WAIT: duration 1493.955ms
[0105_transactions_mock      / 36.602s] Test config file test.conf not found
[0105_transactions_mock      / 36.602s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 36.603s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 36.603s] PRODUCE: duration 0.596ms
[0105_transactions_mock      / 36.603s] Changing transaction coordinator from 1 to 2
[0105_transactions_mock      / 36.604s] rd_kafka_abort_transaction(rk, -1): duration 1.039ms
[0105_transactions_mock      / 36.604s] Changing transaction coordinator from 2 to 3
[0105_transactions_mock      / 36.605s] rd_kafka_begin_transaction(rk): duration 0.146ms
[0105_transactions_mock      / 36.605s] Test config file test.conf not found
[0105_transactions_mock      / 36.605s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 36.605s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 36.605s] PRODUCE: duration 0.218ms
[<MAIN>                      / 44.439s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      / 36.058s] Rebalance #3: _ASSIGN_PARTITIONS: 4 partition(s)
[0106_cgrp_sess_timeout      / 36.059s] ASSIGN.PARTITIONS: duration 0.104ms
[0106_cgrp_sess_timeout      / 36.059s] assign: assigned 4 partition(s)
[0106_cgrp_sess_timeout      / 36.059s] Closing consumer
[0106_cgrp_sess_timeout      / 36.059s] Rebalance #4: _REVOKE_PARTITIONS: 4 partition(s)
[0106_cgrp_sess_timeout      / 36.059s] Performing async commit
[<MAIN>                      / 45.439s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      / 37.059s] UNASSIGN.PARTITIONS: duration 0.179ms
[0106_cgrp_sess_timeout      / 37.059s] unassign: unassigned current partitions
[0106_cgrp_sess_timeout      / 37.060s] CONSUMER.CLOSE: duration 1001.267ms
[0106_cgrp_sess_timeout      / 37.064s] [ Test session timeout with async commit PASSED ]
[0106_cgrp_sess_timeout      / 37.064s] [ Test session timeout with auto commit ]
[0106_cgrp_sess_timeout      / 37.065s] Test config file test.conf not found
[0106_cgrp_sess_timeout      / 37.066s] Created    kafka instance 0106_cgrp_sess_timeout#producer-79
[0106_cgrp_sess_timeout      / 37.066s] Test config file test.conf not found
[0106_cgrp_sess_timeout      / 37.066s] Produce to test [0]: messages #0..100
[0106_cgrp_sess_timeout      / 37.067s] SUM(POLL): duration 0.001ms
[0106_cgrp_sess_timeout      / 37.067s] PRODUCE: duration 0.266ms
[0106_cgrp_sess_timeout      / 37.071s] PRODUCE.DELIVERY.WAIT: duration 4.705ms
[0106_cgrp_sess_timeout      / 37.072s] Test config file test.conf not found
[0106_cgrp_sess_timeout      / 37.072s] Setting test timeout to 30s * 2.7
[0106_cgrp_sess_timeout      / 37.073s] Created    kafka instance 0106_cgrp_sess_timeout#consumer-80
[0106_cgrp_sess_timeout      / 37.074s] Waiting for initial assignment (_ASSIGN_PARTITIONS) for 7s
[0105_transactions_mock      / 38.106s] PRODUCE.DELIVERY.WAIT: duration 1500.773ms
[0105_transactions_mock      / 38.106s] Test config file test.conf not found
[0105_transactions_mock      / 38.106s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 38.106s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 38.107s] PRODUCE: duration 0.621ms
[0105_transactions_mock      / 38.107s] Changing transaction coordinator from 3 to 4
[0105_transactions_mock      / 38.108s] rd_kafka_abort_transaction(rk, -1): duration 1.060ms
[0105_transactions_mock      / 38.108s] Changing transaction coordinator from 4 to 5
[0105_transactions_mock      / 38.108s] rd_kafka_begin_transaction(rk): duration 0.149ms
[0105_transactions_mock      / 38.108s] Test config file test.conf not found
[0105_transactions_mock      / 38.108s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 38.108s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 38.108s] PRODUCE: duration 0.243ms
[<MAIN>                      / 46.439s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 39.602s] PRODUCE.DELIVERY.WAIT: duration 1493.607ms
[0105_transactions_mock      / 39.602s] Changing transaction coordinator from 5 to 1
[0105_transactions_mock      / 39.602s] Test config file test.conf not found
[0105_transactions_mock      / 39.602s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 39.603s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 39.603s] PRODUCE: duration 0.567ms
[0105_transactions_mock      / 39.603s] Changing transaction coordinator from 1 to 2
[0105_transactions_mock      / 39.604s] rd_kafka_abort_transaction(rk, -1): duration 1.003ms
[0105_transactions_mock      / 39.604s] Changing transaction coordinator from 2 to 3
[0105_transactions_mock      / 39.604s] rd_kafka_begin_transaction(rk): duration 0.202ms
[0105_transactions_mock      / 39.604s] Test config file test.conf not found
[0105_transactions_mock      / 39.604s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 39.605s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 39.605s] PRODUCE: duration 0.205ms
[<MAIN>                      / 47.439s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[<MAIN>                      / 48.440s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 41.107s] PRODUCE.DELIVERY.WAIT: duration 1501.943ms
[0105_transactions_mock      / 41.107s] Test config file test.conf not found
[0105_transactions_mock      / 41.107s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 41.107s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 41.107s] PRODUCE: duration 0.594ms
[0105_transactions_mock      / 41.109s] rd_kafka_commit_transaction(rk, -1): duration 1.493ms
[0105_transactions_mock      / 41.109s] Changing transaction coordinator from 3 to 4
[0105_transactions_mock      / 41.109s] rd_kafka_begin_transaction(rk): duration 0.177ms
[0105_transactions_mock      / 41.109s] Test config file test.conf not found
[0105_transactions_mock      / 41.109s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 41.110s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 41.110s] PRODUCE: duration 0.209ms
[<MAIN>                      / 49.440s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      / 41.076s] Rebalance #1: _ASSIGN_PARTITIONS: 4 partition(s)
[0106_cgrp_sess_timeout      / 41.076s] ASSIGN.PARTITIONS: duration 0.322ms
[0106_cgrp_sess_timeout      / 41.076s] assign: assigned 4 partition(s)
[0105_transactions_mock      / 42.602s] PRODUCE.DELIVERY.WAIT: duration 1492.794ms
[0105_transactions_mock      / 42.602s] Test config file test.conf not found
[0105_transactions_mock      / 42.603s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 42.603s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 42.603s] PRODUCE: duration 0.595ms
[0105_transactions_mock      / 42.603s] Changing transaction coordinator from 4 to 5
[0105_transactions_mock      / 42.604s] rd_kafka_abort_transaction(rk, -1): duration 1.056ms
[0105_transactions_mock      / 42.604s] Changing transaction coordinator from 5 to 1
[0105_transactions_mock      / 42.605s] rd_kafka_begin_transaction(rk): duration 0.147ms
[0105_transactions_mock      / 42.605s] Test config file test.conf not found
[0105_transactions_mock      / 42.605s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 42.605s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 42.605s] PRODUCE: duration 0.210ms
[<MAIN>                      / 50.440s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      / 42.077s] consume: consume 10 messages
[0106_cgrp_sess_timeout      / 42.078s] CONSUME: duration 0.023ms
[0106_cgrp_sess_timeout      / 42.078s] consume: consumed 10/10 messages (0/-1 EOFs)
[0106_cgrp_sess_timeout      / 42.078s] Waiting for session timeout revoke (_REVOKE_PARTITIONS) for 9s
[<MAIN>                      / 51.441s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 44.106s] PRODUCE.DELIVERY.WAIT: duration 1501.320ms
[0105_transactions_mock      / 44.106s] Changing transaction coordinator from 1 to 2
[0105_transactions_mock      / 44.107s] Test config file test.conf not found
[0105_transactions_mock      / 44.107s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 44.107s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 44.107s] PRODUCE: duration 0.569ms
[0105_transactions_mock      / 44.108s] rd_kafka_abort_transaction(rk, -1): duration 1.126ms
[0105_transactions_mock      / 44.108s] Changing transaction coordinator from 2 to 3
[0105_transactions_mock      / 44.109s] rd_kafka_begin_transaction(rk): duration 0.137ms
[0105_transactions_mock      / 44.109s] Test config file test.conf not found
[0105_transactions_mock      / 44.109s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 44.109s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 44.109s] PRODUCE: duration 0.211ms
[<MAIN>                      / 52.441s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 45.603s] PRODUCE.DELIVERY.WAIT: duration 1494.585ms
[0105_transactions_mock      / 45.604s] Test config file test.conf not found
[0105_transactions_mock      / 45.604s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 45.604s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 45.604s] PRODUCE: duration 0.640ms
[0105_transactions_mock      / 45.604s] Changing transaction coordinator from 3 to 4
[0105_transactions_mock      / 45.606s] rd_kafka_abort_transaction(rk, -1): duration 1.100ms
[0105_transactions_mock      / 45.606s] Changing transaction coordinator from 4 to 5
[0105_transactions_mock      / 45.606s] rd_kafka_begin_transaction(rk): duration 0.143ms
[0105_transactions_mock      / 45.606s] Test config file test.conf not found
[0105_transactions_mock      / 45.606s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 45.606s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 45.606s] PRODUCE: duration 0.212ms
[<MAIN>                      / 53.441s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[<MAIN>                      / 54.441s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 47.107s] PRODUCE.DELIVERY.WAIT: duration 1501.347ms
[0105_transactions_mock      / 47.108s] Test config file test.conf not found
[0105_transactions_mock      / 47.108s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 47.108s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 47.108s] PRODUCE: duration 0.624ms
[0105_transactions_mock      / 47.110s] rd_kafka_abort_transaction(rk, -1): duration 1.245ms
[0105_transactions_mock      / 47.110s] Changing transaction coordinator from 5 to 1
[0105_transactions_mock      / 47.110s] rd_kafka_begin_transaction(rk): duration 0.136ms
[0105_transactions_mock      / 47.110s] Test config file test.conf not found
[0105_transactions_mock      / 47.110s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 47.110s] SUM(POLL): duration 0.000ms
[0105_transactions_mock      / 47.110s] PRODUCE: duration 0.209ms
[<MAIN>                      / 55.442s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 48.603s] PRODUCE.DELIVERY.WAIT: duration 1492.847ms
[0105_transactions_mock      / 48.603s] Changing transaction coordinator from 1 to 2
[0105_transactions_mock      / 48.603s] Test config file test.conf not found
[0105_transactions_mock      / 48.603s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 48.604s] SUM(POLL): duration 0.000ms
[0105_transactions_mock      / 48.604s] PRODUCE: duration 0.573ms
[0105_transactions_mock      / 48.604s] Changing transaction coordinator from 2 to 3
[0105_transactions_mock      / 48.606s] rd_kafka_commit_transaction(rk, -1): duration 1.768ms
[0105_transactions_mock      / 48.606s] Changing transaction coordinator from 3 to 4
[0105_transactions_mock      / 48.606s] rd_kafka_begin_transaction(rk): duration 0.129ms
[0105_transactions_mock      / 48.606s] Test config file test.conf not found
[0105_transactions_mock      / 48.606s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 48.606s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 48.606s] PRODUCE: duration 0.229ms
[<MAIN>                      / 56.442s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
%4|1594295338.152|SESSTMOUT|0106_cgrp_sess_timeout#consumer-80| [thrd:main]: Consumer group session timed out (in join-state started) after 6000 ms without a successful response from the group coordinator (broker 1, last error was Broker: Not coordinator): revoking assignment and rejoining group
[0106_cgrp_sess_timeout      / 48.079s] Rebalance #2: _REVOKE_PARTITIONS: 4 partition(s)
[0106_cgrp_sess_timeout      / 48.079s] UNASSIGN.PARTITIONS: duration 0.210ms
[0106_cgrp_sess_timeout      / 48.079s] unassign: unassigned current partitions
%4|1594295338.356|COMMITFAIL|0106_cgrp_sess_timeout#consumer-80| [thrd:main]: Offset commit (unassign) failed for 4/4 partition(s): Broker: Unknown member: test[0]@17(Broker: Unknown member)
[<MAIN>                      / 57.442s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      / 49.079s] Waiting for second assignment (_ASSIGN_PARTITIONS) for 7s
[0105_transactions_mock      / 50.107s] PRODUCE.DELIVERY.WAIT: duration 1500.163ms
[0105_transactions_mock      / 50.107s] Test config file test.conf not found
[0105_transactions_mock      / 50.107s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 50.107s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 50.107s] PRODUCE: duration 0.634ms
[0105_transactions_mock      / 50.107s] Changing transaction coordinator from 4 to 5
[0105_transactions_mock      / 50.109s] rd_kafka_abort_transaction(rk, -1): duration 1.086ms
[0105_transactions_mock      / 50.109s] Changing transaction coordinator from 5 to 1
[0105_transactions_mock      / 50.109s] rd_kafka_begin_transaction(rk): duration 0.132ms
[0105_transactions_mock      / 50.109s] Test config file test.conf not found
[0105_transactions_mock      / 50.109s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 50.109s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 50.109s] PRODUCE: duration 0.233ms
[<MAIN>                      / 58.442s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 51.604s] PRODUCE.DELIVERY.WAIT: duration 1494.353ms
[0105_transactions_mock      / 51.604s] Test config file test.conf not found
[0105_transactions_mock      / 51.604s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 51.604s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 51.604s] PRODUCE: duration 0.623ms
[0105_transactions_mock      / 51.604s] Changing transaction coordinator from 1 to 2
[0105_transactions_mock      / 51.606s] rd_kafka_abort_transaction(rk, -1): duration 1.069ms
[0105_transactions_mock      / 51.606s] Changing transaction coordinator from 2 to 3
[0105_transactions_mock      / 51.606s] rd_kafka_begin_transaction(rk): duration 0.131ms
[0105_transactions_mock      / 51.606s] Test config file test.conf not found
[0105_transactions_mock      / 51.606s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 51.606s] SUM(POLL): duration 0.000ms
[0105_transactions_mock      / 51.606s] PRODUCE: duration 0.229ms
[<MAIN>                      / 59.443s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[<MAIN>                      / 60.443s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 53.108s] PRODUCE.DELIVERY.WAIT: duration 1501.518ms
[0105_transactions_mock      / 53.108s] Changing transaction coordinator from 3 to 4
[0105_transactions_mock      / 53.108s] Test config file test.conf not found
[0105_transactions_mock      / 53.108s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 53.109s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 53.109s] PRODUCE: duration 0.615ms
[0105_transactions_mock      / 53.110s] rd_kafka_abort_transaction(rk, -1): duration 1.265ms
[0105_transactions_mock      / 53.110s] Changing transaction coordinator from 4 to 5
[0105_transactions_mock      / 53.110s] rd_kafka_begin_transaction(rk): duration 0.182ms
[0105_transactions_mock      / 53.110s] Test config file test.conf not found
[0105_transactions_mock      / 53.110s] Produce to test [-1]: messages #0..50
[0105_transactions_mock      / 53.111s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 53.111s] PRODUCE: duration 0.219ms
[<MAIN>                      / 61.443s] 2 test(s) running: 0105_transactions_mock 0106_cgrp_sess_timeout
[0105_transactions_mock      / 54.603s] PRODUCE.DELIVERY.WAIT: duration 1491.919ms
[0105_transactions_mock      / 54.603s] Test config file test.conf not found
[0105_transactions_mock      / 54.603s] Produce to test [-1]: messages #50..100
[0105_transactions_mock      / 54.603s] SUM(POLL): duration 0.001ms
[0105_transactions_mock      / 54.603s] PRODUCE: duration 0.669ms
[0105_transactions_mock      / 54.603s] Changing transaction coordinator from 5 to 1
[0105_transactions_mock      / 54.605s] rd_kafka_abort_transaction(rk, -1): duration 1.030ms
[0105_transactions_mock      / 54.608s] [ Test switching coordinators: PASS ]
[0105_transactions_mock      / 54.608s] 0105_transactions_mock: duration 54608.020ms
[0105_transactions_mock      / 54.608s] ================= Test 0105_transactions_mock PASSED =================
[<MAIN>                      / 62.443s] 1 test(s) running: 0106_cgrp_sess_timeout
[0106_cgrp_sess_timeout      / 54.079s] Rebalance #3: _ASSIGN_PARTITIONS: 4 partition(s)
[0106_cgrp_sess_timeout      / 54.079s] ASSIGN.PARTITIONS: duration 0.105ms
[0106_cgrp_sess_timeout      / 54.079s] assign: assigned 4 partition(s)
[0106_cgrp_sess_timeout      / 54.080s] Closing consumer
[0106_cgrp_sess_timeout      / 54.080s] Rebalance #4: _REVOKE_PARTITIONS: 4 partition(s)
[0106_cgrp_sess_timeout      / 54.080s] UNASSIGN.PARTITIONS: duration 0.076ms
[0106_cgrp_sess_timeout      / 54.080s] unassign: unassigned current partitions
[0106_cgrp_sess_timeout      / 54.080s] CONSUMER.CLOSE: duration 0.452ms
[0106_cgrp_sess_timeout      / 54.084s] [ Test session timeout with auto commit PASSED ]
[0106_cgrp_sess_timeout      / 54.084s] 0106_cgrp_sess_timeout: duration 54084.121ms
[0106_cgrp_sess_timeout      / 54.084s] ================= Test 0106_cgrp_sess_timeout PASSED =================
[<MAIN>                      / 63.444s] ALL-TESTS: duration 63443.484ms
[<MAIN>                      / 63.445s] # Test report written to test_report_20200709124905.json
[<MAIN>                      / 63.445s] 3 thread(s) in use by librdkafka, waiting...
[<MAIN>                      / 64.445s] 3 thread(s) in use by librdkafka
[<MAIN>                      / 64.445s] TEST FAILURE
### Test "<MAIN>" failed at /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/tests/test.c:1467:test_wait_exit() at Thu Jul  9 12:49:06 2020: ###
3 thread(s) still active in librdkafka
[<MAIN>                      / 64.445s] TEST FAILURE
### Test "<MAIN>" failed at /home/tkloczko/rpmbuild/BUILD/librdkafka-1.4.4/tests/test.c:1761:main() at Thu Jul  9 12:49:06 2020: ###
1 test(s) failed, see previous errors
conf_destroy called (opaque 0x7f4bc0001580 vs 0x7f4c1c269034) ici 0x7f4bc0001580
on_destroy: 0x7f4bc0003a90
conf_destroy called (opaque 0x7f4bc0003a90 vs 0x7f4c1c269034) ici 0x7f4bc0003a90
conf_destroy called (opaque 0x7f4bc0004870 vs 0x7f4c1c269034) ici 0x7f4bc0004870
conf_destroy called (opaque 0x7f4bc0005690 vs 0x7f4c1c269034) ici 0x7f4bc0005690
conf_destroy called (opaque 0x7f4bc0005ee0 vs 0x7f4c1c269034) ici 0x7f4bc0005ee0
TEST 20200709124905 (bare, scenario default) SUMMARY
#==================================================================#
| <MAIN>                                   |     PASSED |  63.444s |
| 0000_unittests                           |     PASSED |   8.329s |
| 0004_conf                                |     PASSED |   0.023s |
| 0006_symbols                             |     PASSED |   0.000s |
| 0009_mock_cluster                        |     PASSED |   2.022s |
| 0025_timers                              |     FAILED |  63.442s | do_test_stats_timer():134: 1/10 intervals failed
| 0033_regex_subscribe_local               |     PASSED |   0.067s |
| 0037_destroy_hang_local                  |     PASSED |   1.003s |
| 0039_event                               |     PASSED |   0.002s |
| 0043_no_connection                       |     PASSED |   1.003s |
| 0046_rkt_cache                           |     PASSED |   0.001s |
| 0053_stats_timing                        |     PASSED |   1.202s |
| 0058_log                                 |     PASSED |   2.003s |
| 0062_stats_event                         |     PASSED |   0.502s |
| 0066_plugins                             |     PASSED |   0.003s |
| 0072_headers_ut                          |     PASSED |   1.215s |
| 0074_producev                            |     PASSED |   0.001s |
| 0078_c_from_cpp                          |     PASSED |   0.001s |
| 0079_fork                                |    SKIPPED |   0.000s | Filtered due to negative test flags
| 0080_admin_ut                            |     FAILED |  60.514s | do_test_CreateTopics():217: CreateTopics: expected duration 0 <= 483 <= 50 ms
| 0084_destroy_flags_local                 |     PASSED |   4.032s |
| 0086_purge_local                         |     PASSED |   0.309s |
| 0095_all_brokers_down                    |     PASSED |   4.027s |
| 0100_thread_interceptors                 |     PASSED |   0.820s |
| 0103_transactions_local                  |     PASSED |   7.027s |
| 0104_fetch_from_follower_mock            |     PASSED |  18.380s |
| 0105_transactions_mock                   |     PASSED |  54.608s |
| 0106_cgrp_sess_timeout                   |     PASSED |  54.084s |
#==================================================================#
<end of output>
Test time =  64.50 sec
----------------------------------------------------------
Test Failed.
"RdKafkaTestBrokerLess" end time: Jul 09 12:49 BST
"RdKafkaTestBrokerLess" time elapsed: 00:01:04
----------------------------------------------------------

End testing: Jul 09 12:49 BST

[edenhill]

There is no test.conf, so likely no test cluster available. See tests/README.md

[edenhill]

Re LTO: LDFLAGS=-flto CFLAGS=-flto ./configure && make -j seems to work well on OSX.

[kloczek]

Try to build static library with LTo. In tests/Makefile you have hardcoded:

CFLAGS += -I../src
CXXFLAGS += -I../src -I../src-cpp
LDFLAGS += -rdynamic -L../src -L../src-cpp

It means that you are not supporting off-tree build (using cmake it is possible to execute cmake -B <build_dir>; make -C <build_dir>. And this is only tip of the iceberg which you custom build framework is not supporting and even plain ac/am/lt framework supports. Really maintaing that is waste of time and effort.

[edenhill]

If you need an example of statically linked programs, look in examples/, they are all statically linked. What is your use-case for a statically linked test-runner?

OOTB is not supported and sometimes desired, but there's been minimal demand for it. The CMake build system is provided best-effortedly for users who need it, but relies on it being maintained by those same users, so feel free to submit PRs to improve what you think is missing.

There are no plans to replace mklove, it does the job for the use-cases we support and does not impose any extra dependencies (such as cmake). No matter what build system is used by default there will be users with special needs of something else.

[kloczek]

I don't need that static libraries but on wrinting my own build procedure I don't want to be surprised in the future that your build framework is not covering some standard ac/am/lt feartures to which is possible to inject within build process without changeing single character in rpm package spec file in which ac/am/lt build framework is used .. sorry.

This is why I decide to choose cmake (to not be srprised and chase my own tail long time after cleaning today librdkafka.spec file for librdkafka. You should be able understand meaning and importance some (de facto or de jure) standards as you ar using the same software on OSX and other systems. Isn't it?

[edenhill]

What modifications did you need to in librdkafka.spec?

[kloczek]

For now? None. My librdkafka.spec is finished with disabled execution of the %check and added refference to this ticket.

[kloczek]

Fantastic. Ticket closed without investigation or solving teported (test suite failing) issue :) I see first time ever such behaviour ..

[edenhill]

My second comment pointed out that there was no test configuration and to consult the tests/README.md file: https://github.com/edenhill/librdkafka/issues/2979#issuecomment-656090977

The easiest way to set up a test cluster is to use trivup:

$ cd tests
$ pip install -r requirements.txt
$ ./interactive_broker_version.py 2.5.0
trivup-shell$ make   # to run the tests, or use whatever CMake does
trivup-shell$ exit   #cluster is destroyed
$

[kloczek]

Thx for that advice. If you will not see any other my comments here it will mean that above helped :)

[kloczek]

I just have been trying to package missing two mpython modules and fond that https://bitbucket.org/Dando_Real_ITA/json-comment/ disapeared. Do you know maybe what happens with that module?🤔 (on pypi last version was in 2019)