predixy crashed with SIGABRT

[wonnyz]

-- Logs begin at Sun 2018-05-13 02:21:16 +07, end at Tue 2018-05-15 12:42:52 +07. --
May 14 15:05:57 redis04 start-stop-daemon[156313]: *** Error in `/opt/redis/bin/predixy': free(): corrupted unsorted chunks: 0x00007fa85407d500 ***
May 14 15:05:57 redis04 start-stop-daemon[156313]: ======= Backtrace: =========
May 14 15:05:57 redis04 start-stop-daemon[156313]: /lib/x86_64-linux-gnu/libc.so.6(+0x777e5)[0x7fa8777227e5]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /lib/x86_64-linux-gnu/libc.so.6(+0x8037a)[0x7fa87772b37a]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /lib/x86_64-linux-gnu/libc.so.6(cfree+0x4c)[0x7fa87772f53c]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy(_ZN7Request5clearEv+0x9e7)[0x48a007]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy(_ZN16AcceptConnection5writeEP7HandlerP5IOVeci+0xe99)[0x453fd9]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy(_ZN16AcceptConnection10writeEventEP7Handler+0x28)[0x4545f8]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy(_ZN7Handler25postAcceptConnectionEventEv+0x80)[0x4aa4a0]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy(_ZN7Handler3runEv+0x56)[0x4ad956]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy(execute_native_thread_routine+0x20)[0x4e9560]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7fa877f9b6ba]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fa8777b241d]
May 14 15:05:57 redis04 start-stop-daemon[156313]: ======= Memory map: ========
May 14 15:05:57 redis04 start-stop-daemon[156313]: 00400000-00543000 r-xp 00000000 08:03 36176100                           /opt/redis/bin/predixy
May 14 15:05:57 redis04 start-stop-daemon[156313]: 00743000-00749000 r--p 00143000 08:03 36176100                           /opt/redis/bin/predixy
May 14 15:05:57 redis04 start-stop-daemon[156313]: 00749000-0074b000 rw-p 00149000 08:03 36176100                           /opt/redis/bin/predixy
May 14 15:05:57 redis04 start-stop-daemon[156313]: 0074b000-00760000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 00875000-008da000 rw-p 00000000 00:00 0                                  [heap]
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa83c000000-7fa83c021000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa83c021000-7fa840000000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa844000000-7fa844098000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa844098000-7fa848000000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa848000000-7fa8480b1000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8480b1000-7fa84c000000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa84c000000-7fa84c0b6000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa84c0b6000-7fa850000000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa850000000-7fa8500a0000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8500a0000-7fa854000000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa854000000-7fa8540a4000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8540a4000-7fa858000000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa858000000-7fa8580a9000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8580a9000-7fa85c000000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa85d7fb000-7fa85d7fc000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa85d7fc000-7fa85dffc000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa85dffc000-7fa85dffd000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa85dffd000-7fa85e7fd000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa85e7fd000-7fa85e7fe000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa85e7fe000-7fa85effe000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa85effe000-7fa85efff000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa85efff000-7fa85f7ff000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa85f7ff000-7fa85f800000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa85f800000-7fa860000000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa860000000-7fa860097000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa860097000-7fa864000000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa864000000-7fa86409c000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa86409c000-7fa868000000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa868000000-7fa868096000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa868096000-7fa86c000000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa86c000000-7fa86c094000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa86c094000-7fa870000000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa870000000-7fa870023000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa870023000-7fa874000000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8746a5000-7fa8746a6000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8746a6000-7fa874ea6000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa874ea6000-7fa874ea7000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa874ea7000-7fa8756a7000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8756a7000-7fa8756a8000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8756a8000-7fa875ea8000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa875ea8000-7fa875ea9000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa875ea9000-7fa8766a9000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8766a9000-7fa8766aa000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8766aa000-7fa876eaa000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa876eaa000-7fa876eab000 ---p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa876eab000-7fa8776ab000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8776ab000-7fa87786b000 r-xp 00000000 08:03 33951993                   /lib/x86_64-linux-gnu/libc-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa87786b000-7fa877a6b000 ---p 001c0000 08:03 33951993                   /lib/x86_64-linux-gnu/libc-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa877a6b000-7fa877a6f000 r--p 001c0000 08:03 33951993                   /lib/x86_64-linux-gnu/libc-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa877a6f000-7fa877a71000 rw-p 001c4000 08:03 33951993                   /lib/x86_64-linux-gnu/libc-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa877a71000-7fa877a75000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa877a75000-7fa877a8b000 r-xp 00000000 08:03 33948183                   /lib/x86_64-linux-gnu/libgcc_s.so.1
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa877a8b000-7fa877c8a000 ---p 00016000 08:03 33948183                   /lib/x86_64-linux-gnu/libgcc_s.so.1
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa877c8a000-7fa877c8b000 rw-p 00015000 08:03 33948183                   /lib/x86_64-linux-gnu/libgcc_s.so.1
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa877c8b000-7fa877d93000 r-xp 00000000 08:03 33951989                   /lib/x86_64-linux-gnu/libm-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa877d93000-7fa877f92000 ---p 00108000 08:03 33951989                   /lib/x86_64-linux-gnu/libm-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa877f92000-7fa877f93000 r--p 00107000 08:03 33951989                   /lib/x86_64-linux-gnu/libm-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa877f93000-7fa877f94000 rw-p 00108000 08:03 33951989                   /lib/x86_64-linux-gnu/libm-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa877f94000-7fa877fac000 r-xp 00000000 08:03 33951992                   /lib/x86_64-linux-gnu/libpthread-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa877fac000-7fa8781ab000 ---p 00018000 08:03 33951992                   /lib/x86_64-linux-gnu/libpthread-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8781ab000-7fa8781ac000 r--p 00017000 08:03 33951992                   /lib/x86_64-linux-gnu/libpthread-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8781ac000-7fa8781ad000 rw-p 00018000 08:03 33951992                   /lib/x86_64-linux-gnu/libpthread-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8781ad000-7fa8781b1000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8781b1000-7fa8781d7000 r-xp 00000000 08:03 33951991                   /lib/x86_64-linux-gnu/ld-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8783a3000-7fa8783ca000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8783d5000-7fa8783d6000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8783d6000-7fa8783d7000 r--p 00025000 08:03 33951991                   /lib/x86_64-linux-gnu/ld-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8783d7000-7fa8783d8000 rw-p 00026000 08:03 33951991                   /lib/x86_64-linux-gnu/ld-2.23.so
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7fa8783d8000-7fa8783d9000 rw-p 00000000 00:00 0
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7ffde7f2e000-7ffde7f4f000 rw-p 00000000 00:00 0                          [stack]
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7ffde7fc0000-7ffde7fc3000 r--p 00000000 00:00 0                          [vvar]
May 14 15:05:57 redis04 start-stop-daemon[156313]: 7ffde7fc3000-7ffde7fc5000 r-xp 00000000 00:00 0                          [vdso]
May 14 15:05:57 redis04 start-stop-daemon[156313]: ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0                  [vsyscall]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy(_Z9traceInfoi+0x12f)[0x4b8a6f]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy[0x4b785d]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /lib/x86_64-linux-gnu/libc.so.6(+0x354b0)[0x7fa8776e04b0]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7fa8776e0428]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fa8776e202a]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /lib/x86_64-linux-gnu/libc.so.6(+0x777ea)[0x7fa8777227ea]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /lib/x86_64-linux-gnu/libc.so.6(+0x8037a)[0x7fa87772b37a]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /lib/x86_64-linux-gnu/libc.so.6(cfree+0x4c)[0x7fa87772f53c]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy(_ZN7Request5clearEv+0x9e7)[0x48a007]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy(_ZN16AcceptConnection5writeEP7HandlerP5IOVeci+0xe99)[0x453fd9]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy(_ZN16AcceptConnection10writeEventEP7Handler+0x28)[0x4545f8]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy(_ZN7Handler25postAcceptConnectionEventEv+0x80)[0x4aa4a0]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy(_ZN7Handler3runEv+0x56)[0x4ad956]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /opt/redis/bin/predixy(execute_native_thread_routine+0x20)[0x4e9560]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7fa877f9b6ba]
May 14 15:05:57 redis04 start-stop-daemon[156313]: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fa8777b241d]
May 14 15:05:59 redis04 systemd[1]: predixy_cluster.service: Main process exited, code=killed, status=6/ABRT
May 14 15:05:59 redis04 systemd[1]: predixy_cluster.service: Unit entered failed state.
May 14 15:05:59 redis04 systemd[1]: predixy_cluster.service: Failed with result 'signal'.
May 14 15:05:59 redis04 systemd[1]: predixy_cluster.service: Service hold-off time over, scheduling restart.
May 14 15:05:59 redis04 systemd[1]: Stopped Redis Cluster Proxy Service.

We're using predixy 1.0.5-pre on Ubuntu 16.04, which is built from latest master.

# uname -a
Linux redis04 4.4.0-121-generic #145-Ubuntu SMP Fri Apr 13 13:47:23 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

configuration attached.
predixy.conf.txt

I think we're experiencing basically same issue as #29.

We're performing load testing on redis cluster, A predixy instance is processing 10K requests per sec. predixy doesn't crash so often, but when it crashes, it is critical.

127.0.0.1:7000> info
# Proxy
Version:1.0.5-pre
Name:
Bind:0.0.0.0:7000
RedisMode:proxy
SingleThread:false
WorkerThreads:10
Uptime:1526354727
UptimeSince:2018-05-15 10:25:27

# SystemResource
UsedMemory:5256256
MaxMemory:0
MaxRSS:8794112
UsedCpuSys:1625.952
UsedCpuUser:682.592

# Stats
Accept:3987
ClientConnections:600
TotalRequests:85803809
TotalResponses:85803814
TotalRecvClientBytes:6244194469
TotalSendServerBytes:6244644215
TotalRecvServerBytes:6760996314
TotalSendClientBytes:6724113683

[fortrue]

Can you reproduce this bug everytime? which commands be used in testing? Is custom commands be used? what's means of the custom command redis_lock_lock.acquire/redis_lock.release/cl.throttle

[wonnyz]

Not every time. (then we couldn't use predixy if predixy crashed every time...)
Yes, they are all custom commands from custom redis modules. We deployed redis modules on all cluster instances. They're working nicely till now.

• redis-lock is a simple distributed lock implementation (in-house) on Redis. Its response is REDISMODULE_OK or REDISMODULE_ERR with details.

redis_lock.acquire key_name uuid ttl_sec

redis_lock.release key_name uuid 

• cl.throttle is redis-cell.

I'll check and post commands used in test later.

[fortrue]

#29, because they modified the source to supports custom command. The issue closed after they update predixy to 4b8f578

[wonnyz]

We used the same approach too! and we too switched to 1.0.5-pre. but I'm wondering if the spot in which predixy crashes is same as #29 , regardless of supporting custom command.

I'm going to use predixy latency monitor to get the exact command list that our service uses.

[fortrue]

They modified the predixy source code then result in predixy crash, are you modified predixy source code too?

[wonnyz]

No. we don't. (for now, at least when we got SIGABRT error) but we get the same results, that makes me embarrassed.

[fortrue]

Can you help to upload the predixy.log?

[wonnyz]

Sorry for late reply. We applied latest patch of branch 'issue32', and ran the load test multiple times.

So far so good!

I'm looking at the logs continuously, no SIGABRT, no hang with SIGSEGV (11).
If there is any further issue, I'll report it.

Many thanks!