{"action":"created","issue":{"url":"https://api.github.com/repos/antirez/redis/issues/5229","repository_url":"https://api.github.com/repos/antirez/redis","labels_url":"https://api.github.com/repos/antirez/redis/issues/5229/labels{/name}","comments_url":"https://api.github.com/repos/antirez/redis/issues/5229/comments","events_url":"https://api.github.com/repos/antirez/redis/issues/5229/events","html_url":"https://github.com/antirez/redis/issues/5229","id":349120807,"node_id":"MDU6SXNzdWUzNDkxMjA4MDc=","number":5229,"title":"slave hung in processUnblockedClients","user":{"login":"oranagra","id":7045099,"node_id":"MDQ6VXNlcjcwNDUwOTk=","avatar_url":"https://avatars1.githubusercontent.com/u/7045099?v=4","gravatar_id":"","url":"https://api.github.com/users/oranagra","html_url":"https://github.com/oranagra","followers_url":"https://api.github.com/users/oranagra/followers","following_url":"https://api.github.com/users/oranagra/following{/other_user}","gists_url":"https://api.github.com/users/oranagra/gists{/gist_id}","starred_url":"https://api.github.com/users/oranagra/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/oranagra/subscriptions","organizations_url":"https://api.github.com/users/oranagra/orgs","repos_url":"https://api.github.com/users/oranagra/repos","events_url":"https://api.github.com/users/oranagra/events{/privacy}","received_events_url":"https://api.github.com/users/oranagra/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":4,"created_at":"2018-08-09T13:10:26Z","updated_at":"2018-08-14T13:57:38Z","closed_at":null,"author_association":"CONTRIBUTOR","body":"Here's an issue i'm unable to figure out. maybe someone can help...\r\n\r\nA slave redis (4.0.9) stopped responding, and ate 100% CPU for some half an hour.\r\n```\r\n~# time redis-cli <port> info all     \r\nCould not connect to Redis at 10.0.1.9:29565: Connection timed out\r\n\r\nreal    2m9.415s\r\nuser    0m0.036s\r\nsys     0m0.011s\r\n```\r\n\r\nThe watchdog was trying to kill it with SIGTERM (10 signals one second apart), but it's not responding to these either. and the log shows:\r\n```\r\n4116:S 08 Aug 15:51:31.685 # == CRITICAL == This slave is sending an error to its master: 'Error running script (call to f_d4d1d1b62afa6d576d81cfbecc482ad7e516d172): @user_script:80: user_script:80: too many results to unpack ' after processing the command 'evalsha'\r\n4116:S 08 Aug 15:57:04.503 # == CRITICAL == This slave is sending an error to its master: 'Error running script (call to f_d4d1d1b62afa6d576d81cfbecc482ad7e516d172): @user_script:80: user_script:80: too many results to unpack ' after processing the command 'evalsha'\r\n4116:signal-handler (1533743958) Received SIGTERM scheduling shutdown...\r\n4116:signal-handler (1533743958) Received SIGTERM scheduling shutdown...\r\n4116:signal-handler (1533743959) Received SIGTERM scheduling shutdown...\r\n4116:signal-handler (1533743960) Received SIGTERM scheduling shutdown...\r\n4116:signal-handler (1533743961) Received SIGTERM scheduling shutdown...\r\n4116:signal-handler (1533743962) Received SIGTERM scheduling shutdown...\r\n4116:signal-handler (1533743963) Received SIGTERM scheduling shutdown...\r\n4116:signal-handler (1533743964) Received SIGTERM scheduling shutdown...\r\n4116:signal-handler (1533743965) Received SIGTERM scheduling shutdown...\r\n4116:signal-handler (1533743966) Received SIGTERM scheduling shutdown...\r\n4116:S 08 Aug 16:02:51.103 # == CRITICAL == This slave is sending an error to its master: 'Error running script (call to f_d4d1d1b62afa6d576d81cfbecc482ad7e516d172): @user_script:80: user_script:80: too many results to unpack ' after processing the command 'evalsha'\r\n4116:S 08 Aug 16:05:38.817 # == CRITICAL == This slave is sending an error to its master: 'Error running script (call to f_d4d1d1b62afa6d576d81cfbecc482ad7e516d172): @user_script:80: user_script:80: too many results to unpack ' after processing the command 'evalsha'\r\n```\r\n\r\nApparently the \"CRITICAL\" errors were present in this database since forever, and were harmless. possibly, a script that's failing on the master's side too, but only after performing some modification, so that redis is forced to replicate it to the slave to fail there too.\r\n\r\nThe fact that we see CRITICAL log messages after the SIGTERM signal was received, is an indication that the process is not hung in an endless loop, but still processing commands (in a long running loop), but does't (yet) read commands from other clients, or get to serverCron to respond to the shutdown_asap flag.\r\n\r\nI sent a SIGSEGV to the slave so that i can get a crash report with stack trace, and this is what i saw:\r\n\r\n```\r\nBacktrace:\r\nredis-server redis-2525.conf *:29565(logStackTrace+0x45)[0x476c65]\r\nredis-server redis-2525.conf *:29565(sigsegvHandler+0xbb)[0x47742b]\r\n/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7fb9f4432390]\r\n/lib/x86_64-linux-gnu/libc.so.6(+0x14dcde)[0x7fb9f41a4cde]\r\nredis-server redis-2525.conf *:29565(sdsrange+0x187)[0x432947]\r\nredis-server redis-2525.conf *:29565(processMultibulkBuffer+0x473)[0x43bc63]\r\nredis-server redis-2525.conf *:29565(processInputBuffer+0xe6)[0x43d246]\r\nredis-server redis-2525.conf *:29565(processUnblockedClients+0x78)[0x496908]\r\nredis-server redis-2525.conf *:29565(beforeSleep+0xb5)[0x429095]\r\nredis-server redis-2525.conf *:29565(aeMain+0x1e)[0x4247de]\r\nredis-server redis-2525.conf *:29565(main+0x4ca)[0x42131a]\r\n/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7fb9f4077830]\r\nredis-server redis-2525.conf *:29565(_start+0x29)[0x421599]\r\n```\r\n\r\nI do know that processInputBuffer may be inefficient in some cases, imagine a command that takes long time to execute, and during that time, a huge (1gb max, assuming there are no bugs) input buffer is collected, then processInputBuffer trims one command (a few bytes) at a time, memmoving the entire 1gb backwards multiple times. but this does not explain a half hour hung. unless there is some way in which readQueryFromClient can be called from within this loop, and keep feeding the loop.\r\n\r\nTheoretically processUnblockedClients should never be executed on slaves, since redis replaces BLPOP with LPOP when it propagates the commands, and obviously all blocking commands are rejected in scripts.\r\nbut there's at least one case which still propagates a blocking command to slaves, and this is BRPOPLPUSH, in the case the key existed when the command was executed on the master and it didn't block.\r\n\r\nIn this case, theoretically, it wouldn't block on the slave side too, but there are cases (e.g. #5171 and others) in which there are data inconsistencies between master and slaves.\r\nso this could explain why we'll have a blocked (and possibly deadlocked) master client... and in case the command was executed with a timeout, we'll also get to processUnblockedClients.\r\n\r\nBut all of that still doesn't explain why the process will be hang in processInputBuffer for half an hour eating 100% CPU.\r\n\r\nif anyone has any idea, let's chat."},"comment":{"url":"https://api.github.com/repos/antirez/redis/issues/comments/412880788","html_url":"https://github.com/antirez/redis/issues/5229#issuecomment-412880788","issue_url":"https://api.github.com/repos/antirez/redis/issues/5229","id":412880788,"node_id":"MDEyOklzc3VlQ29tbWVudDQxMjg4MDc4OA==","user":{"login":"oranagra","id":7045099,"node_id":"MDQ6VXNlcjcwNDUwOTk=","avatar_url":"https://avatars1.githubusercontent.com/u/7045099?v=4","gravatar_id":"","url":"https://api.github.com/users/oranagra","html_url":"https://github.com/oranagra","followers_url":"https://api.github.com/users/oranagra/followers","following_url":"https://api.github.com/users/oranagra/following{/other_user}","gists_url":"https://api.github.com/users/oranagra/gists{/gist_id}","starred_url":"https://api.github.com/users/oranagra/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/oranagra/subscriptions","organizations_url":"https://api.github.com/users/oranagra/orgs","repos_url":"https://api.github.com/users/oranagra/repos","events_url":"https://api.github.com/users/oranagra/events{/privacy}","received_events_url":"https://api.github.com/users/oranagra/received_events","type":"User","site_admin":false},"created_at":"2018-08-14T13:57:38Z","updated_at":"2018-08-14T13:57:38Z","author_association":"CONTRIBUTOR","body":"> @oranagra maybe you set slave-read-only as no on slave? That may del the src key and make BLPOPLPUSH block on slave.\r\n\r\nNo, the slave on that db don't get any traffic except from the master.\r\n\r\nbut when complex scripts are running, maybe a simple divergence of how they are executed or what they see with redis command can result in more data inconsistencies.\r\nso maybe the list key was not only expired, but really missing.."}}
{"actor":{"display_login":"oranagra"}}