{"id":599,"date":"2018-02-11T12:46:57","date_gmt":"2018-02-11T17:46:57","guid":{"rendered":"http:\/\/jasonralph.org\/?p=599"},"modified":"2019-10-09T12:14:36","modified_gmt":"2019-10-09T16:14:36","slug":"python2-7-subprocess-and-rsync-deadlock-strace-timeout","status":"publish","type":"post","link":"https:\/\/jasonralph.org\/?p=599","title":{"rendered":"Python3 Subprocess and Rsync Deadlock Strace Timeout"},"content":{"rendered":"<p>I recently came across a tough to debug issue where I was calling a shell script from python using the <code>subprocess<\/code> module, this shell script called <code>rsync<\/code>, no matter what I would always run into a timeout situation.  I fired up strace and noticed that the process was in a timeout state. <\/p>\n<p><code>select(4, NULL, [3], [3], {60, 0}) = 0 (Timeout)<\/code><\/p>\n<p>I looked at the subprocess documentation and apparently using pipes will fill the system pipe buffer. <\/p>\n<blockquote><p>Warning<\/p>\n<p>This will deadlock when using stdout=PIPE and\/or stderr=PIPE and the child process generates enough output to a pipe such that it blocks waiting for the OS pipe buffer to accept more data. Use communicate() to avoid that. <\/p><\/blockquote>\n<p>I was baffled, I finally took the approach to eliminate <code>stderr<\/code> and <code>stdout<\/code> and just check the return status of the command using <code>run()<\/code>. Here is what I finally came up with, and all was well. <\/p>\n<pre class=\"theme:solarized-dark lang:default decode:true \" >\r\nstdbuf -oL -e0 \/usr\/local\/bin\/rsync --outbuf=N -avz\r\n<\/pre>\n<pre class=\"theme:solarized-dark lang:default decode:true \" >\r\ndef execute_jobs(cmd):\r\n     try:\r\n         logger.info('Start Command: [%s]' % cmd)\r\n         subprocess.run(shlex.split(cmd), check=True)\r\n         logger.info('Command Success: [%s]' % cmd)\r\n     except subprocess.CalledProcessError as e:\r\n         logger.critical('[%s] FATAL: Command failed with error [%s]' % (cmd,e))\r\n<\/pre>\n<p>Hope you find this and it helps you. <\/p>\n","protected":false},"excerpt":{"rendered":"<p>I recently came across a tough to debug issue where I was calling a shell script from python using the subprocess module, this shell script called rsync, no matter what I would always run into a timeout situation. I fired up strace and noticed that the process was in a timeout state. select(4, NULL, [3], [&hellip;]<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[4],"tags":[58,24,57,60,59],"class_list":["post-599","post","type-post","status-publish","format-standard","hentry","category-python","tag-deadlock","tag-python-2","tag-strace","tag-subprocess","tag-timeout"],"_links":{"self":[{"href":"https:\/\/jasonralph.org\/index.php?rest_route=\/wp\/v2\/posts\/599","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/jasonralph.org\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/jasonralph.org\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/jasonralph.org\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/jasonralph.org\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=599"}],"version-history":[{"count":14,"href":"https:\/\/jasonralph.org\/index.php?rest_route=\/wp\/v2\/posts\/599\/revisions"}],"predecessor-version":[{"id":635,"href":"https:\/\/jasonralph.org\/index.php?rest_route=\/wp\/v2\/posts\/599\/revisions\/635"}],"wp:attachment":[{"href":"https:\/\/jasonralph.org\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=599"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/jasonralph.org\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=599"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/jasonralph.org\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=599"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}