Skip to content

Address some failures with new tests for improving debug report #12915

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Merged
madolson merged 1 commit into from
Jan 9, 2024
Merged

Address some failures with new tests for improving debug report #12915

madolson merged 1 commit into from
Jan 9, 2024

Conversation

@madolson
Copy link
Contributor

@madolson madolson commented Jan 6, 2024

Fix a daily test failure because alpine doesn't support stack traces and add in an extra assertion related to making sure the stack trace was printed twice.

https://github.com/redis/redis/actions/runs/7429386274/job/20217983539

@madolson madolson mentioned this pull request Jan 6, 2024
Merged
@sundb
Copy link
Collaborator

sundb commented Jan 7, 2024

@madolson still get stuck.
This is the test log:

### Starting server for test 
10254:C 07 Jan 2024 10:03:17.367 * oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
10254:C 07 Jan 2024 10:03:17.367 * Redis version=255.255.255, bits=64, commit=4c099e62, modified=0, pid=10254, just started
10254:C 07 Jan 2024 10:03:17.367 * Configuration loaded
10254:M 07 Jan 2024 10:03:17.369 * Increased maximum number of open files to 10032 (it was originally set to 256).
10254:M 07 Jan 2024 10:03:17.369 * monotonic clock: POSIX clock_gettime
10254:M 07 Jan 2024 10:03:17.369 # Failed to write PID file: Permission denied
                _._                                                  
           _.-``__ ''-._                                             
      _.-``    `.  `_.  ''-._           Redis 255.255.255 (4c099e62/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._                                  
 (    '      ,       .-`  | `,    )     Running in standalone mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 21112
 |    `-._   `._    /     _.-'    |     PID: 10254
  `-._    `-._  `-./  _.-'    _.-'                                   
 |`-._`-._    `-.__.-'    _.-'_.-'|                                  
 |    `-._`-._        _.-'_.-'    |           https://redis.io       
  `-._    `-._`-.__.-'_.-'    _.-'                                   
 |`-._`-._    `-.__.-'    _.-'_.-'|                                  
 |    `-._`-._        _.-'_.-'    |                                  
  `-._    `-._`-.__.-'_.-'    _.-'                                   
      `-._    `-.__.-'    _.-'                                       
          `-._        _.-'                                           
              `-.__.-'                                               

10254:M 07 Jan 2024 10:03:17.369 # WARNING: The TCP backlog setting of 511 cannot be enforced because kern.ipc.somaxconn is set to the lower value of 128.
10254:M 07 Jan 2024 10:03:17.370 * Server initialized
10254:M 07 Jan 2024 10:03:17.370 * Ready to accept connections tcp
10254:M 07 Jan 2024 10:03:17.370 * Ready to accept connections unix
10254:M 07 Jan 2024 10:03:17.473 - Accepted 127.0.0.1:57111
10254:M 07 Jan 2024 10:03:17.473 - Client closed connection id=3 addr=127.0.0.1:57111 laddr=127.0.0.1:21112 fd=13 name= age=0 idle=0 flags=N db=0 sub=0 psub=0 ssub=0 multi=-1 qbuf=0 qbuf-free=16384 argv-mem=0 multi-mem=0 rbs=16384 rbp=16384 obl=0 oll=0 omem=0 tot-mem=33550 events=r cmd=ping user=default redir=-1 resp=2 lib-name= lib-ver=
10254:M 07 Jan 2024 10:03:17.479 - Accepted 127.0.0.1:57112
10254:M 07 Jan 2024 10:03:17.480 * Module 'infocrash' loaded from /Users/debing.sun/data/redis_fork/tests/modules/crash.so
### Starting test Test module crash when info crashes with a segfault in tests/unit/moduleapi/crash.tcl


=== REDIS BUG REPORT START: Cut & paste starting from here ===
10254:M 07 Jan 2024 10:03:17.480 # Redis 255.255.255 crashed by signal: 10, si_code: 1
10254:M 07 Jan 2024 10:03:17.480 # Accessing address: 0x1018bc000
10254:M 07 Jan 2024 10:03:17.480 # Crashed running the instruction at: 0x10721b488

------ STACK TRACE ------
EIP:
0   crash.so                            0x000000010721b488 segfaultCrash + 40

Backtrace:
0   libclang_rt.tsan_osx_dynamic.dylib  0x00000001018f2e38 _ZN6__tsanL21CallUserSignalHandlerEPNS_11ThreadStateEbbiPN11__sanitizer19__sanitizer_siginfoEPv + 264
1   libclang_rt.tsan_osx_dynamic.dylib  0x00000001018f32a8 _Z10sighandleriPN11__sanitizer19__sanitizer_siginfoEPv + 408
2   libsystem_platform.dylib            0x000000018a4bfa24 _sigtramp + 56
3   ???                                 0xffff80010721b484 0x0 + 18446603340635812996
4   redis-server                        0x0000000100f87d3c modulesCollectInfo + 272
5   redis-server                        0x0000000100e8a810 genRedisInfoString + 14188
6   redis-server                        0x0000000100e8ac8c infoCommand + 772
7   redis-server                        0x0000000100e80090 call + 592
8   redis-server                        0x0000000100e8267c processCommand + 5104
9   redis-server                        0x0000000100e9e3e8 processInputBuffer + 4068
10  redis-server                        0x0000000100e9ca40 readQueryFromClient + 2188
11  redis-server                        0x0000000100fbd248 connSocketEventHandler + 336
12  redis-server                        0x0000000100e65f60 aeProcessEvents + 1224
13  redis-server                        0x0000000100e922c0 main + 24924
14  dyld                                0x000000018a1150e0 start + 2360

------ STACK TRACE DONE ------

------ REGISTERS ------
10254:M 07 Jan 2024 10:03:17.482 # 
x0:00000001018bc000 x1:0000000000001000 x2:0000000000000000 x3:0000000000001000
x4:00000000ffffffff x5:0000000000000000 x6:0000000000000068 x7:0000000000001a00
x8:0000000000000078 x9:000000010135a900 x10:0000000000000002 x11:000008020317a080
x12:0000000000000000 x13:0000000003070000 x14:0000000000000000 x15:0000000000000019
x16:0000000302b03cb8 x17:0000000101958920 x18:0000000000000000 x19:0000000100e8a810
x20:0000000000000000 x21:0000000104f02fc0 x22:000000010522e9d3 x23:0000000105306090
x24:0000000100fd1e30 x25:0000000000000000 x26:000000010721b460 x27:0000000100fd10b0
x28:0000000105906b80 fp:000000016efc9cf0 lr:c77700010721b484
sp:000000016efc9cf0 pc:000000010721b488 cpsr:00001000

10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cff) -> 0000000000000000
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cfe) -> 0000000101095c78
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cfd) -> 00000001010968b0
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cfc) -> 0000000000000000
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cfb) -> 0000000000000000
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cfa) -> 0000000000000001
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cf9) -> 0000000101073ed0
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cf8) -> 000000010522e9d3
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cf7) -> 154b800100000000
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cf6) -> 0000000000000000
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cf5) -> 000000010522e9d3
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cf4) -> 0000000104f02fc0
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cf3) -> 0000000105906b80
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cf2) -> 0000000104f02fc0
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cf1) -> 0000000100f87d3c
10254:M 07 Jan 2024 10:03:17.482 # (000000016efc9cf0) -> 000000016efc9d80

------ INFO OUTPUT ------
# Server
redis_version:255.255.255
redis_git_sha1:4c099e62
redis_git_dirty:0
redis_build_id:3490826d59364f97
redis_mode:standalone
os:Darwin 23.1.0 arm64
arch_bits:64
monotonic_clock:POSIX clock_gettime
multiplexing_api:kqueue
atomicvar_api:c11-builtin
gcc_version:4.2.1
process_id:10254
process_supervised:no
run_id:74377287c3e2982adad7b80433c896e6cf72c04d
tcp_port:21112
server_time_usec:1704592997480805
uptime_in_seconds:0
uptime_in_days:0
hz:10
configured_hz:10
lru_clock:10094181
executable:/Users/debing.sun/data/redis_fork/src/redis-server
config_file:/Users/debing.sun/data/redis_fork/./tests/tmp/redis.conf.10204.4
io_threads_active:0
listener0:name=tcp,bind=127.0.0.1,port=21112
listener1:name=unix,bind=/Users/debing.sun/data/redis_fork/tests/tmp/server.10204.3/socket

# Clients
connected_clients:1
cluster_connections:0
maxclients:10000
client_recent_max_input_buffer:0
client_recent_max_output_buffer:0
blocked_clients:0
tracking_clients:0
pubsub_clients:0
clients_in_timeout_table:0
total_blocking_keys:0
total_blocking_keys_on_nokey:0

# Memory
used_memory:1182184
used_memory_human:1.13M
used_memory_rss:60129280
used_memory_rss_human:57.34M
used_memory_peak:1182184
used_memory_peak_human:1.13M
used_memory_peak_perc:100.16%
used_memory_overhead:1055907
used_memory_startup:1055726
used_memory_dataset:126277
used_memory_dataset_perc:99.86%
allocator_allocated:1055870
allocator_active:60097536
allocator_resident:60097536
total_system_memory:38654705664
total_system_memory_human:36.00G
used_memory_lua:31744
used_memory_vm_eval:31744
used_memory_lua_human:31.00K
used_memory_scripts_eval:0
number_of_cached_scripts:0
number_of_functions:0
number_of_libraries:0
used_memory_vm_functions:32768
used_memory_vm_total:64512
used_memory_vm_total_human:63.00K
used_memory_functions:181
used_memory_scripts:181
used_memory_scripts_human:181B
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
allocator_frag_ratio:56.92
allocator_frag_bytes:59041666
allocator_rss_ratio:1.00
allocator_rss_bytes:0
rss_overhead_ratio:1.00
rss_overhead_bytes:31744
mem_fragmentation_ratio:56.95
mem_fragmentation_bytes:59073410
mem_not_counted_for_evict:0
mem_replication_backlog:0
mem_total_replication_buffers:0
mem_clients_slaves:0
mem_clients_normal:0
mem_cluster_links:0
mem_aof_buffer:0
mem_allocator:libc
active_defrag_running:0
lazyfree_pending_objects:0
lazyfreed_objects:0

# Persistence
loading:0
async_loading:0
current_cow_peak:0
current_cow_size:0
current_cow_size_age:0
current_fork_perc:0.00
current_save_keys_processed:0
current_save_keys_total:0
rdb_changes_since_last_save:0
rdb_bgsave_in_progress:0
rdb_last_save_time:1704592997
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:-1
rdb_current_bgsave_time_sec:-1
rdb_saves:0
rdb_last_cow_size:0
rdb_last_load_keys_expired:0
rdb_last_load_keys_loaded:0
aof_enabled:0
aof_rewrite_in_progress:0
aof_rewrite_scheduled:0
aof_last_rewrite_time_sec:-1
aof_current_rewrite_time_sec:-1
aof_last_bgrewrite_status:ok
aof_rewrites:0
aof_rewrites_consecutive_failures:0
aof_last_write_status:ok
aof_last_cow_size:0
module_fork_in_progress:0
module_fork_last_cow_size:0

# Stats
total_connections_received:2
total_commands_processed:3
instantaneous_ops_per_sec:0
total_net_input_bytes:162
total_net_output_bytes:17
total_net_repl_input_bytes:0
total_net_repl_output_bytes:0
instantaneous_input_kbps:0.00
instantaneous_output_kbps:0.00
instantaneous_input_repl_kbps:0.00
instantaneous_output_repl_kbps:0.00
rejected_connections:0
sync_full:0
sync_partial_ok:0
sync_partial_err:0
expired_keys:0
expired_stale_perc:0.00
expired_time_cap_reached_count:0
expire_cycle_cpu_milliseconds:0
evicted_keys:0
evicted_clients:0
total_eviction_exceeded_time:0
current_eviction_exceeded_time:0
keyspace_hits:0
keyspace_misses:0
pubsub_channels:0
pubsub_patterns:0
pubsubshard_channels:0
latest_fork_usec:0
total_forks:0
migrate_cached_sockets:0
slave_expires_tracked_keys:0
active_defrag_hits:0
active_defrag_misses:0
active_defrag_key_hits:0
active_defrag_key_misses:0
total_active_defrag_time:0
current_active_defrag_time:0
tracking_total_keys:0
tracking_total_items:0
tracking_total_prefixes:0
unexpected_error_replies:0
total_error_replies:0
dump_payload_sanitizations:0
total_reads_processed:5
total_writes_processed:3
io_threaded_reads_processed:0
io_threaded_writes_processed:0
client_query_buffer_limit_disconnections:0
client_output_buffer_limit_disconnections:0
reply_buffer_shrinks:0
reply_buffer_expands:0
eventloop_cycles:8
eventloop_duration_sum:1210
eventloop_duration_cmd_sum:726
instantaneous_eventloop_cycles_per_sec:0
instantaneous_eventloop_duration_usec:0
acl_access_denied_auth:0
acl_access_denied_cmd:0
acl_access_denied_key:0
acl_access_denied_channel:0

# Replication
role:master
connected_slaves:0
master_failover_state:no-failover
master_replid:17085375ee1e7fcffa28c5e88b84471466bd0977
master_replid2:0000000000000000000000000000000000000000
master_repl_offset:0
second_repl_offset:-1
repl_backlog_active:0
repl_backlog_size:1048576
repl_backlog_first_byte_offset:0
repl_backlog_histlen:0

# CPU
used_cpu_sys:0.035917
used_cpu_user:0.030325
used_cpu_sys_children:0.000000
used_cpu_user_children:0.000000

# Modules
module:name=infocrash,ver=1,api=1,filters=0,usedby=[],using=[],options=[]

# Commandstats
cmdstat_ping:calls=1,usec=2,usec_per_call=2.00,rejected_calls=0,failed_calls=0
cmdstat_module|load:calls=1,usec=718,usec_per_call=718.00,rejected_calls=0,failed_calls=0
cmdstat_select:calls=1,usec=6,usec_per_call=6.00,rejected_calls=0,failed_calls=0

# Errorstats

# Latencystats
latency_percentiles_usec_ping:p50=2.007,p99=2.007,p99.9=2.007
latency_percentiles_usec_module|load:p50=720.895,p99=720.895,p99.9=720.895
latency_percentiles_usec_select:p50=6.015,p99=6.015,p99.9=6.015

# Cluster
cluster_enabled:0

# Keyspace

------ CLIENT LIST OUTPUT ------
id=4 addr=127.0.0.1:57112 laddr=127.0.0.1:21112 fd=13 name= age=0 idle=0 flags=N db=9 sub=0 psub=0 ssub=0 multi=-1 qbuf=29 qbuf-free=16355 argv-mem=13 multi-mem=0 rbs=16384 rbp=16384 obl=0 oll=0 omem=0 tot-mem=33579 events=r cmd=info user=default redir=-1 resp=2 lib-name= lib-ver=

------ CURRENT CLIENT INFO ------
id=4 addr=127.0.0.1:57112 laddr=127.0.0.1:21112 fd=13 name= age=0 idle=0 flags=N db=9 sub=0 psub=0 ssub=0 multi=-1 qbuf=29 qbuf-free=16355 argv-mem=13 multi-mem=0 rbs=16384 rbp=16384 obl=0 oll=0 omem=0 tot-mem=33579 events=r cmd=info user=default redir=-1 resp=2 lib-name= lib-ver=
argc: '2'
argv[0]: '"info"'
argv[1]: '"infocrash"'

------ EXECUTING CLIENT INFO ------
id=4 addr=127.0.0.1:57112 laddr=127.0.0.1:21112 fd=13 name= age=0 idle=0 flags=N db=9 sub=0 psub=0 ssub=0 multi=-1 qbuf=29 qbuf-free=16355 argv-mem=13 multi-mem=0 rbs=16384 rbp=16384 obl=0 oll=0 omem=0 tot-mem=33579 events=r cmd=info user=default redir=-1 resp=2 lib-name= lib-ver=
argc: '2'
argv[0]: '"info"'
argv[1]: '"infocrash"'

------ MODULES INFO OUTPUT ------
10254:signal-handler (1704593229) Received SIGINT scheduling shutdown...

oranagra
oranagra reviewed Jan 7, 2024
View reviewed changes
oranagra
oranagra approved these changes Jan 7, 2024
View reviewed changes
Copy link
Member

@oranagra oranagra left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@sundb i don't think i understand your comment.
@madolson i'm approving this PR so that once you resolve the issues (or reply that they're false), you can merge this.

@sundb
Copy link
Collaborator

sundb commented Jan 7, 2024

@oranagra this is following #12857 (comment)

@sundb
Copy link
Collaborator

sundb commented Jan 7, 2024

@madolson I revert debug.c from #12857, and it's still stuck, so a recursive crash before #12857 would also cause SANIZITER to be stuck.
@oranagra I think we can leave it and deal with it when we add thread CI in the future.

@madolson
Copy link
Contributor Author

madolson commented Jan 9, 2024

Ok, I'd like to unblock the daily and it sounds like we have independent issues with running with sanitizer=thread.

@madolson madolson merged commit 8bb9a28 into redis:unstable Jan 9, 2024
@sundb
Copy link
Collaborator

sundb commented Jan 13, 2024

just for record, the reason stuck when running with sanitizer=thread:
SANITIZER catches the signal, and the signal handler is CallUserSignalHandler(), which gets stuck when the recursion crashes because CallUserSignalHandler is not reentrant.

roggervalf pushed a commit to roggervalf/redis that referenced this pull request Feb 11, 2024
@madolson @roggervalf
Address some failures with new tests for improving debug report (redi…
1494350 
…s#12915)

Fix a daily test failure because alpine doesn't support stack traces and
add in an extra assertion related to making sure the stack trace was
printed twice.
funny-dog pushed a commit to funny-dog/redis that referenced this pull request Sep 17, 2025
@madolson
Address some failures with new tests for improving debug report (redi…
7722b0f 
…s#12915)

Fix a daily test failure because alpine doesn't support stack traces and
add in an extra assertion related to making sure the stack trace was
printed twice.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@oranagra oranagra oranagra approved these changes

Assignees

No one assigned

Labels

None yet

Projects

Redis 7.4
Status: Done

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

3 participants

@madolson @sundb @oranagra