EXC_BAD_ACCESS on test_producer.py #44
Description
Probably it requires an update librdkafka to 1.8.2.
But I do following steps:
- Run zookeper and kafka (nothing interesting I downloaded them via brew)
- Run "tarantool tests/app.lua"
- Run "pytest test_producer.py" (I saw that one time test passed. It seems it's floating bug)
lldb:
➜ kafka git:(master) ✗ lldb tarantool
(lldb) target create "tarantool"
Current executable set to 'tarantool' (x86_64).
(lldb) r tests/app.lua
Process 46864 launched: '/usr/local/bin/tarantool' (x86_64)
2021-10-30 03:00:00.241 [46864] main/103/app.lua C> Tarantool 2.8.2-0-gfc96d10
2021-10-30 03:00:00.242 [46864] main/103/app.lua C> log level 5
2021-10-30 03:00:00.242 [46864] main/103/app.lua I> wal/engine cleanup is paused
2021-10-30 03:00:00.242 [46864] main/103/app.lua I> mapping 268435456 bytes for memtx tuple arena...
2021-10-30 03:00:00.242 [46864] main/103/app.lua I> Actual slab_alloc_factor calculated on the basis of desired slab_alloc_factor = 1.044274
2021-10-30 03:00:00.245 [46864] main/103/app.lua I> mapping 134217728 bytes for vinyl tuple arena...
2021-10-30 03:00:00.246 [46864] main/103/app.lua I> Recovering snapshot with schema version 2.3.1
2021-10-30 03:00:00.247 [46864] main/103/app.lua I> instance uuid 3a44a196-d129-4b2a-988e-4997614115fc
2021-10-30 03:00:00.248 [46864] main/103/app.lua I> instance vclock {1: 11}
2021-10-30 03:00:00.248 [46864] main/103/app.lua I> tx_binary: stopped
2021-10-30 03:00:00.249217+0300 tarantool[46864:6792710] [si_destination_compare] send failed: Invalid argument
2021-10-30 03:00:00.249235+0300 tarantool[46864:6792710] [si_destination_compare] send failed: Undefined error: 0
2021-10-30 03:00:00.249242+0300 tarantool[46864:6792710] [si_destination_compare] send failed: Invalid argument
2021-10-30 03:00:00.249 [46864] main/103/app.lua I> tx_binary: bound to [::]:3301
2021-10-30 03:00:00.250 [46864] main/103/app.lua I> recovery start
2021-10-30 03:00:00.250 [46864] main/103/app.lua I> recovering from `./00000000000000000000.snap'
2021-10-30 03:00:00.250 [46864] main/103/app.lua I> cluster uuid 33eaa93a-cdb7-4412-84a4-0e7fee97979d
2021-10-30 03:00:00.258 [46864] main/103/app.lua I> assigned id 1 to replica 3a44a196-d129-4b2a-988e-4997614115fc
2021-10-30 03:00:00.258 [46864] main/103/app.lua I> recover from `./00000000000000000000.xlog'
2021-10-30 03:00:00.259 [46864] main/103/app.lua I> done `./00000000000000000000.xlog'
2021-10-30 03:00:00.260 [46864] main/103/app.lua I> recover from `./00000000000000000002.xlog'
2021-10-30 03:00:00.260 [46864] main/103/app.lua recovery.cc:161 W> file `./00000000000000000002.xlog` wasn't correctly closed
2021-10-30 03:00:00.260 [46864] main/103/app.lua I> recover from `./00000000000000000011.xlog'
2021-10-30 03:00:00.260 [46864] main/103/app.lua recovery.cc:161 W> file `./00000000000000000011.xlog` wasn't correctly closed
2021-10-30 03:00:00.261 [46864] main/103/app.lua I> ready to accept requests
2021-10-30 03:00:00.261 [46864] main/103/app.lua C> leaving orphan mode
2021-10-30 03:00:00.261 [46864] main/104/gc I> wal/engine cleanup is resumed
2021-10-30 03:00:00.261 [46864] main/103/app.lua I> set 'log_level' configuration option to 5
2021-10-30 03:00:00.261 [46864] main/105/checkpoint_daemon I> scheduled next checkpoint for Sat Oct 30 04:10:38 2021
2021-10-30 03:00:00.261 [46864] main/103/app.lua I> set 'listen' configuration option to "3301"
2021-10-30 03:00:00.261 [46864] main/103/app.lua I> set 'log_format' configuration option to "plain"
2021-10-30 03:00:00.296 [46864] main C> entering the event loop
2021-10-30 03:00:15.077 [46864] main/120/lua I> got log: 5 - CONFWARN - [thrd:app]: No `bootstrap.servers` configured: client will not be able to connect to Kafka cluster
2021-10-30 03:00:15.087 [46864] main/118/main producer.lua:55 E> successfully sent value '1'
2021-10-30 03:00:15.098 [46864] main/118/main producer.lua:55 E> successfully sent value '2'
2021-10-30 03:00:15.110 [46864] main/118/main producer.lua:55 E> successfully sent value '3'
2021-10-30 03:00:26.159 [46864] main/124/lua I> got log: 5 - CONFWARN - [thrd:app]: No `bootstrap.servers` configured: client will not be able to connect to Kafka cluster
2021-10-30 03:00:27.159 [46864] main/125/lua producer.lua:19 E> got error: kafka:9090/bootstrap: Connect to ipv4#127.0.0.1:9090 failed: Connection refused (after 2ms in state CONNECT)
2021-10-30 03:00:27.159 [46864] main/125/lua producer.lua:19 E> got error: 1/1 brokers are down
2021-10-30 03:00:27.159 [46864] main/124/lua I> got log: 3 - FAIL - [thrd:kafka:9090/bootstrap]: kafka:9090/bootstrap: Connect to ipv4#127.0.0.1:9090 failed: Connection refused (after 2ms in state CONNECT)
2021-10-30 03:00:28.160 [46864] main/125/lua producer.lua:19 E> got error: kafka:9090/bootstrap: Connect to ipv4#127.0.0.1:9090 failed: Connection refused (after 0ms in state CONNECT, 1 identical error(s) suppressed)
2021-10-30 03:00:28.160 [46864] main/124/lua I> got log: 3 - FAIL - [thrd:kafka:9090/bootstrap]: kafka:9090/bootstrap: Connect to ipv4#127.0.0.1:9090 failed: Connection refused (after 0ms in state CONNECT, 1 identical error(s) suppressed)
2021-10-30 03:00:28.278 [46864] main/128/lua I> got log: 7 - BRKMAIN - [thrd::0/internal]: :0/internal: Enter main broker thread
2021-10-30 03:00:28.278 [46864] main/128/lua I> got log: 7 - INIT - [thrd:app]: librdkafka v1.8.2 (0x10802ff) rdkafka#producer-3 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_gssapi,sasl_plain,sasl_scram,plugins,zstd,sasl_oauthbearer, GCC GXX PKGCONFIG OSXLD LIBDL PLUGINS ZLIB SSL SASL_CYRUS ZSTD HDRHISTOGRAM LZ4_EXT SYSLOG SNAPPY SOCKEM SASL_SCRAM SASL_OAUTHBEARER CRC32C_HW, debug 0x46)
2021-10-30 03:00:28.278 [46864] main/128/lua I> got log: 5 - CONFWARN - [thrd:app]: No `bootstrap.servers` configured: client will not be able to connect to Kafka cluster
2021-10-30 03:00:28.278 [46864] main/128/lua I> got log: 7 - BROKER - [thrd:app]: kafka:9092/bootstrap: Added new broker with NodeId -1
2021-10-30 03:00:28.278 [46864] main/128/lua I> got log: 7 - CONNECT - [thrd:app]: kafka:9092/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))
2021-10-30 03:00:28.278 [46864] main/128/lua I> got log: 7 - BRKMAIN - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Enter main broker thread
2021-10-30 03:00:28.278 [46864] main/128/lua I> got log: 7 - CONNECT - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Received CONNECT op
2021-10-30 03:00:28.278 [46864] main/128/lua I> got log: 7 - STATE - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
2021-10-30 03:00:28.278 [46864] main/128/lua I> got log: 7 - CONNECT - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: broker in state TRY_CONNECT connecting
2021-10-30 03:00:28.278 [46864] main/128/lua I> got log: 7 - STATE - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
2021-10-30 03:00:29.279 [46864] main/128/lua I> got log: 7 - CONNECT - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Connecting to ipv4#127.0.0.1:9092 (plaintext) with socket 25
2021-10-30 03:00:29.279 [46864] main/128/lua I> got log: 7 - CONNECT - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Connected to ipv4#127.0.0.1:9092
2021-10-30 03:00:29.279 [46864] main/128/lua I> got log: 7 - CONNECTED - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Connected (#1)
2021-10-30 03:00:29.279 [46864] main/128/lua I> got log: 7 - FEATURE - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
2021-10-30 03:00:29.279 [46864] main/128/lua I> got log: 7 - STATE - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Broker changed state CONNECT -> APIVERSION_QUERY
2021-10-30 03:00:29.279 [46864] main/128/lua I> got log: 7 - FEATURE - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer,ZSTD,SaslAuthReq
2021-10-30 03:00:29.279 [46864] main/128/lua I> got log: 7 - STATE - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Broker changed state APIVERSION_QUERY -> UP
2021-10-30 03:00:29.279 [46864] main/128/lua I> got log: 7 - BROKER - [thrd:main]: 192.168.100.51:9092/0: Added new broker with NodeId 0
2021-10-30 03:00:29.279 [46864] main/128/lua I> got log: 7 - CLUSTERID - [thrd:main]: kafka:9092/bootstrap: ClusterId update "" -> "UnpL3226RjmTpLn0anNZqA"
2021-10-30 03:00:29.279 [46864] main/128/lua I> got log: 7 - CONTROLLERID - [thrd:main]: kafka:9092/bootstrap: ControllerId update -1 -> 0
2021-10-30 03:00:29.279 [46864] main/128/lua I> got log: 7 - BRKMAIN - [thrd:192.168.100.51:9092/0]: 192.168.100.51:9092/0: Enter main broker thread
2021-10-30 03:00:56.771 [46864] main/133/lua I> got log: 5 - CONFWARN - [thrd:app]: No `bootstrap.servers` configured: client will not be able to connect to Kafka cluster
2021-10-30 03:00:56.780 [46864] main/131/main producer.lua:55 E> successfully sent value '1'
2021-10-30 03:00:56.791 [46864] main/131/main producer.lua:55 E> successfully sent value '2'
2021-10-30 03:00:56.801 [46864] main/131/main producer.lua:55 E> successfully sent value '3'
2021-10-30 03:01:07.859 [46864] main/137/lua I> got log: 5 - CONFWARN - [thrd:app]: No `bootstrap.servers` configured: client will not be able to connect to Kafka cluster
2021-10-30 03:01:08.861 [46864] main/138/lua producer.lua:19 E> got error: kafka:9090/bootstrap: Connect to ipv4#127.0.0.1:9090 failed: Connection refused (after 2ms in state CONNECT)
2021-10-30 03:01:08.861 [46864] main/138/lua producer.lua:19 E> got error: 1/1 brokers are down
2021-10-30 03:01:08.861 [46864] main/137/lua I> got log: 3 - FAIL - [thrd:kafka:9090/bootstrap]: kafka:9090/bootstrap: Connect to ipv4#127.0.0.1:9090 failed: Connection refused (after 2ms in state CONNECT)
2021-10-30 03:01:09.862 [46864] main/138/lua producer.lua:19 E> got error: kafka:9090/bootstrap: Connect to ipv4#127.0.0.1:9090 failed: Connection refused (after 3ms in state CONNECT, 1 identical error(s) suppressed)
2021-10-30 03:01:09.862 [46864] main/137/lua I> got log: 3 - FAIL - [thrd:kafka:9090/bootstrap]: kafka:9090/bootstrap: Connect to ipv4#127.0.0.1:9090 failed: Connection refused (after 3ms in state CONNECT, 1 identical error(s) suppressed)
2021-10-30 03:01:09.983 [46864] main/141/lua I> got log: 7 - INIT - [thrd:app]: librdkafka v1.8.2 (0x10802ff) rdkafka#producer-6 initialized (builtin.features gzip,snappy,ssl,sasl,regex,lz4,sasl_gssapi,sasl_plain,sasl_scram,plugins,zstd,sasl_oauthbearer, GCC GXX PKGCONFIG OSXLD LIBDL PLUGINS ZLIB SSL SASL_CYRUS ZSTD HDRHISTOGRAM LZ4_EXT SYSLOG SNAPPY SOCKEM SASL_SCRAM SASL_OAUTHBEARER CRC32C_HW, debug 0x46)
2021-10-30 03:01:09.983 [46864] main/141/lua I> got log: 7 - BRKMAIN - [thrd::0/internal]: :0/internal: Enter main broker thread
2021-10-30 03:01:09.983 [46864] main/141/lua I> got log: 5 - CONFWARN - [thrd:app]: No `bootstrap.servers` configured: client will not be able to connect to Kafka cluster
2021-10-30 03:01:09.983 [46864] main/141/lua I> got log: 7 - BROKER - [thrd:app]: kafka:9092/bootstrap: Added new broker with NodeId -1
2021-10-30 03:01:09.983 [46864] main/141/lua I> got log: 7 - CONNECT - [thrd:app]: kafka:9092/bootstrap: Selected for cluster connection: bootstrap servers added (broker has 0 connection attempt(s))
2021-10-30 03:01:09.983 [46864] main/141/lua I> got log: 7 - BRKMAIN - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Enter main broker thread
2021-10-30 03:01:09.983 [46864] main/141/lua I> got log: 7 - CONNECT - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Received CONNECT op
2021-10-30 03:01:09.983 [46864] main/141/lua I> got log: 7 - STATE - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Broker changed state INIT -> TRY_CONNECT
2021-10-30 03:01:09.983 [46864] main/141/lua I> got log: 7 - CONNECT - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: broker in state TRY_CONNECT connecting
2021-10-30 03:01:09.983 [46864] main/141/lua I> got log: 7 - STATE - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Broker changed state TRY_CONNECT -> CONNECT
2021-10-30 03:01:10.983 [46864] main/141/lua I> got log: 7 - CONNECT - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Connecting to ipv4#127.0.0.1:9092 (plaintext) with socket 25
2021-10-30 03:01:10.983 [46864] main/141/lua I> got log: 7 - CONNECT - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Connected to ipv4#127.0.0.1:9092
2021-10-30 03:01:10.983 [46864] main/141/lua I> got log: 7 - CONNECTED - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Connected (#1)
2021-10-30 03:01:10.983 [46864] main/141/lua I> got log: 7 - FEATURE - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Updated enabled protocol features +ApiVersion to ApiVersion
2021-10-30 03:01:10.983 [46864] main/141/lua I> got log: 7 - STATE - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Broker changed state CONNECT -> APIVERSION_QUERY
2021-10-30 03:01:10.983 [46864] main/141/lua I> got log: 7 - FEATURE - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Updated enabled protocol features to MsgVer1,ApiVersion,BrokerBalancedConsumer,ThrottleTime,Sasl,SaslHandshake,BrokerGroupCoordinator,LZ4,OffsetTime,MsgVer2,IdempotentProducer,ZSTD,SaslAuthReq
2021-10-30 03:01:10.983 [46864] main/141/lua I> got log: 7 - STATE - [thrd:kafka:9092/bootstrap]: kafka:9092/bootstrap: Broker changed state APIVERSION_QUERY -> UP
2021-10-30 03:01:10.983 [46864] main/141/lua I> got log: 7 - BROKER - [thrd:main]: 192.168.100.51:9092/0: Added new broker with NodeId 0
2021-10-30 03:01:10.983 [46864] main/141/lua I> got log: 7 - CLUSTERID - [thrd:main]: kafka:9092/bootstrap: ClusterId update "" -> "UnpL3226RjmTpLn0anNZqA"
2021-10-30 03:01:10.983 [46864] main/141/lua I> got log: 7 - CONTROLLERID - [thrd:main]: kafka:9092/bootstrap: ControllerId update -1 -> 0
2021-10-30 03:01:10.983 [46864] main/141/lua I> got log: 7 - BRKMAIN - [thrd:192.168.100.51:9092/0]: 192.168.100.51:9092/0: Enter main broker thread
Process 46864 stopped
* thread #4, name = 'coio', stop reason = EXC_BAD_ACCESS (code=EXC_I386_GPFLT)
frame #0: 0x00007fff203fed86 libsystem_pthread.dylib`pthread_mutex_lock + 4
libsystem_pthread.dylib`pthread_mutex_lock:
-> 0x7fff203fed86 <+4>: cmpq $0x4d55545a, (%rdi) ; imm = 0x4D55545A
0x7fff203fed8d <+11>: jne 0x7fff203fee02 ; <+128>
0x7fff203fed8f <+13>: movl 0xc(%rdi), %eax
0x7fff203fed92 <+16>: movl %eax, %ecx
Target 0: (tarantool) stopped.
(lldb) bt
* thread #4, name = 'coio', stop reason = EXC_BAD_ACCESS (code=EXC_I386_GPFLT)
* frame #0: 0x00007fff203fed86 libsystem_pthread.dylib`pthread_mutex_lock + 4
frame #1: 0x0000000102fdbba5 tntkafka.dylib`queue_push(queue=0x6d726554203a5d70, value=0x0000000102c1e0c0) at queue.c:92:5 [opt]
frame #2: 0x0000000102fd7f9a tntkafka.dylib`log_callback(rd_kafka=<unavailable>, level=7, fac="DESTROY", buf=<unavailable>) at callbacks.c:56:17 [opt]
frame #3: 0x000000011e5456f3 librdkafka.1.dylib`rd_kafka_log0 + 563
frame #4: 0x000000011e5469a0 librdkafka.1.dylib`rd_kafka_destroy_app + 832
frame #5: 0x0000000102fdb3be tntkafka.dylib`wait_producer_destroy(args=<unavailable>) at producer.c:414:5 [opt]
frame #6: 0x000000010015d81e tarantool`coio_on_call + 23
frame #7: 0x00000001003019a7 tarantool`etp_proc + 395
frame #8: 0x00007fff204038fc libsystem_pthread.dylib`_pthread_start + 224
frame #9: 0x00007fff203ff443 libsystem_pthread.dylib`thread_start + 15
pytest:
➜ tests git:(master) ✗ pytest test_producer.py
===================================== test session starts =====================================
platform darwin -- Python 3.9.7, pytest-6.2.5, py-1.10.0, pluggy-0.13.1
rootdir: /Users/o.babin/Projects/kafka/tests
plugins: Faker-8.1.3
collected 3 items
test_producer.py ..F [100%]
========================================== FAILURES ===========================================
_______________________________ test_producer_should_log_debug ________________________________
self = <tarantool.connection.Connection object at 0x1083b6d60>, to_read = 5
def _recv(self, to_read):
buf = b""
while to_read > 0:
try:
> tmp = self._socket.recv(to_read)
E socket.timeout: timed out
/usr/local/lib/python3.9/site-packages/tarantool/connection.py:247: timeout
During handling of the above exception, another exception occurred:
def test_producer_should_log_debug():
server = get_server()
server.call("producer.create", ["kafka:9092", {"debug": "broker,topic,msg"}])
time.sleep(2)
response = server.call("producer.get_logs", [])
assert len(response) > 0
assert len(response[0]) > 0
> server.call("producer.close", [])
test_producer.py:110:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
/usr/local/lib/python3.9/site-packages/tarantool/connection.py:413: in call
response = self._send_request(request)
/usr/local/lib/python3.9/site-packages/tarantool/connection.py:381: in _send_request
return self._send_request_wo_reconnect(request)
/usr/local/lib/python3.9/site-packages/tarantool/connection.py:296: in _send_request_wo_reconnect
response = request.response_class(self, self._read_response())
/usr/local/lib/python3.9/site-packages/tarantool/connection.py:280: in _read_response
length = msgpack.unpackb(self._recv(5))
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
self = <tarantool.connection.Connection object at 0x1083b6d60>, to_read = 5
def _recv(self, to_read):
buf = b""
while to_read > 0:
try:
tmp = self._socket.recv(to_read)
except OverflowError:
self._socket.close()
err = socket.error(
errno.ECONNRESET,
"Too big packet. Closing connection to server"
)
raise NetworkError(err)
except socket.error:
err = socket.error(
errno.ECONNRESET,
"Lost connection to server during query"
)
> raise NetworkError(err)
E tarantool.error.NetworkError: (54, 'Connection reset by peer')
/usr/local/lib/python3.9/site-packages/tarantool/connection.py:260: NetworkError
====================================== warnings summary =======================================
test_producer.py::test_producer_should_produce_msgs
/Users/o.babin/Projects/kafka/tests/test_producer.py:59: DeprecationWarning: The loop argument is deprecated since Python 3.8, and scheduled for removal in Python 3.10.
await asyncio.wait_for(consume(), 10, loop=loop)
-- Docs: https://docs.pytest.org/en/stable/warnings.html
=================================== short test summary info ===================================
FAILED test_producer.py::test_producer_should_log_debug - tarantool.error.NetworkError: (54,...
=========================== 1 failed, 2 passed, 1 warning in 25.52s ===========================
I guess (but I'm not completely sure) that it's a raise when some fiber/thread closes producer but another tries to write to it. It looks as use-after-free.