{"action":"created","issue":{"url":"https://api.github.com/repos/hypertable/hypertable/issues/13","labels_url":"https://api.github.com/repos/hypertable/hypertable/issues/13/labels{/name}","comments_url":"https://api.github.com/repos/hypertable/hypertable/issues/13/comments","events_url":"https://api.github.com/repos/hypertable/hypertable/issues/13/events","html_url":"https://github.com/hypertable/hypertable/issues/13","id":54652047,"number":13,"title":"issue783 test failure","user":{"login":"nuggetwheat","id":11298,"avatar_url":"https://avatars.githubusercontent.com/u/11298?v=3","gravatar_id":"","url":"https://api.github.com/users/nuggetwheat","html_url":"https://github.com/nuggetwheat","followers_url":"https://api.github.com/users/nuggetwheat/followers","following_url":"https://api.github.com/users/nuggetwheat/following{/other_user}","gists_url":"https://api.github.com/users/nuggetwheat/gists{/gist_id}","starred_url":"https://api.github.com/users/nuggetwheat/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/nuggetwheat/subscriptions","organizations_url":"https://api.github.com/users/nuggetwheat/orgs","repos_url":"https://api.github.com/users/nuggetwheat/repos","events_url":"https://api.github.com/users/nuggetwheat/events{/privacy}","received_events_url":"https://api.github.com/users/nuggetwheat/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":3,"created_at":"2015-01-17T05:59:49Z","updated_at":"2015-01-18T23:59:49Z","closed_at":null,"body":"issue783 test hung and eventually timed out:\r\n\r\n<pre>\r\n        Start 189: Defects-issue783-offload1\r\n189/278 Test #189: Defects-issue783-offload1 ................***Failed  1843.66 sec\r\n</pre>\r\nThe log shows this:\r\n<pre>\r\n189/278 Testing: Defects-issue783-offload1\r\n189/278 Test: Defects-issue783-offload1\r\nCommand: \"/bin/env\" \"INSTALL_DIR=/opt/hypertable/doug/0.9.8.4\" \"/home/doug/src/hypertable/tests/integration/defects/issue783/run1.sh\"\r\nDirectory: /home/doug/build/hypertable/debug/tests/integration/defects/issue783\r\n\"Defects-issue783-offload1\" start time: Jan 16 18:56 PST\r\nOutput:\r\n----------------------------------------------------------\r\n=======================\r\nDefect #783 - OFFLOAD 1\r\n=======================\r\nFsBroker OK\r\nShutdown thrift broker complete\r\nShutdown hyperspace complete\r\nShutdown range server complete\r\nShutdown hypertable master complete\r\nRemoved /hypertable/servers in FS\r\nRemoved /hypertable/tables in FS\r\nCleared hyperspace\r\nShutdown FS Broker complete\r\nFsBroker OK\r\nHyperspace OK\r\nStarted Hypertable.Master\r\n\r\nWelcome to the hypertable command interpreter.\r\nFor information about Hypertable, visit http://hypertable.com\r\n\r\nType 'help' for a list of commands, or 'help shell' for a\r\nlist of shell meta commands.\r\n\r\n\r\n  Elapsed time:  0.00 s\r\n\r\n  Elapsed time:  0.00 s\r\n\r\n  Elapsed time:  2.83 s\r\n\r\n  Elapsed time:  2.08 s\r\n\r\n0%   10   20   30   40   50   60   70   80   90   100%\r\n|----|----|----|----|----|----|----|----|----|----|\r\n***************************************************\r\n\r\n\r\n        Elapsed time: 5.56 s\r\nTotal cells inserted: 100000\r\nThroughput (cells/s): 17978.48\r\nTotal bytes inserted: 30700000\r\nThroughput (bytes/s): 5519391.85\r\n\r\nwait_for_file /opt/hypertable/doug/0.9.8.4/run/monitoring/rangeservers/rs1_stats_v0.rrd\r\n-rw-rw-r-- 1 doug doug 3843960 Jan 16 18:57 /opt/hypertable/doug/0.9.8.4/run/monitoring/rangeservers/rs1_stats_v0.rrd\r\nwait_for_file /opt/hypertable/doug/0.9.8.4/run/monitoring/rangeservers/rs2_stats_v0.rrd\r\n-rw-rw-r-- 1 doug doug 3843960 Jan 16 18:57 /opt/hypertable/doug/0.9.8.4/run/monitoring/rangeservers/rs2_stats_v0.rrd\r\nwait_for_file /opt/hypertable/doug/0.9.8.4/run/monitoring/rangeservers/rs3_stats_v0.rrd\r\n-rw-rw-r-- 1 doug doug 3843960 Jan 16 18:57 /opt/hypertable/doug/0.9.8.4/run/monitoring/rangeservers/rs3_stats_v0.rrd\r\n\r\n  Elapsed time:  0.00 s\r\n\r\n  Elapsed time:  0.00 s\r\n\r\n  Elapsed time:  0.00 s\r\n\r\n  Elapsed time:  2.07 s\r\n1421463424 WARN Hypertable.Master : (/home/doug/src/hypertable/src/cc/Hypertable/Master/Context.cc:345) RangeServer rs2: disk use 100% exceeds t\r\nhreshold; will not assign ranges\r\n\r\n  Elapsed time:  0.00 s\r\n\r\n  Elapsed time:  0.00 s\r\n1421465228 WARN hypertable : (/home/doug/src/hypertable/src/cc/AsyncComm/IOHandlerData.cc:599) Received response for non-pending event (id=17762\r\n34,version=1,total_len=695)\r\n1421465228 ERROR hypertable : dump_error_history (/home/doug/src/hypertable/src/cc/Hypertable/Lib/RangeLocator.h:154): Hypertable::Exception: Pr\r\noblem creating scanner on second-level METADATA (start row = 2:0002436) - HYPERTABLE request timeout\r\n\tat int Hypertable::RangeLocator::find(const Hypertable::TableIdentifier*, const char*, Hypertable::RangeLocationInfo*, Hypertable::Timer\r\n&, bool) (/home/doug/src/hypertable/src/cc/Hypertable/Lib/RangeLocator.cc:444)\r\n\tat void Hypertable::Lib::RangeServer::Client::do_create_scanner(const Hypertable::CommAddress&, const Hypertable::TableIdentifier&, cons\r\nt Hypertable::RangeSpec&, const Hypertable::Lib::ScanSpec&, Hypertable::ScanBlock&, int32_t) (/home/doug/src/hypertable/src/cc/Hypertable/Lib/Ra\r\nngeServer/Client.cc:282): RangeServer create_scanner() failure : Event: type=ERROR \"HYPERTABLE request timeout\" from=192.168.17.11:15871\r\n1421465228 ERROR hypertable : retry_or_abort (/home/doug/src/hypertable/src/cc/Hypertable/Lib/IntervalScannerAsync.cc:405): Hypertable::Exceptio\r\nn: Locating range for table 2 row='0002436' - HYPERTABLE request timeout\r\n\tat void Hypertable::IntervalScannerAsync::find_range_and_start_scan(const char*, bool) (/home/doug/src/hypertable/src/cc/Hypertable/Lib/\r\nIntervalScannerAsync.cc:251)\r\n\tat void Hypertable::RangeLocator::find_loop(const Hypertable::TableIdentifier*, const char*, Hypertable::RangeLocationInfo*, Hypertable:\r\n:Timer&, bool) (/home/doug/src/hypertable/src/cc/Hypertable/Lib/RangeLocator.cc:249): Locating range for table 2 row='0002436'\r\n1421465228 ERROR hypertable : handle_error (/home/doug/src/hypertable/src/cc/Hypertable/Lib/TableScannerAsync.cc:496): Hypertable::Exception: Ev\r\nent: type=MESSAGE version=1 total_len=68 header_len=38 header_checksum=1581830720 flags=8 id=1776232 gid=0 timeout_ms=0 payload_checksum=0 comma\r\nnd=2 from=192.168.17.11:15870 - RANGE SERVER range not found\r\nError: Event: type=MESSAGE version=1 total_len=68 header_len=38 header_checksum=1581830720 flags=8 id=1776232 gid=0 timeout_ms=0 payload_checksu\r\nm=0 command=2 from=192.168.17.11:15870 - RANGE SERVER range not found\r\n</pre>\r\nNotice the time difference between the WARN log line and the log line before it (1421465228-1421463424=1804).  My guess is this is some sort of deadlock.\r\n"},"comment":{"url":"https://api.github.com/repos/hypertable/hypertable/issues/comments/70433130","html_url":"https://github.com/hypertable/hypertable/issues/13#issuecomment-70433130","issue_url":"https://api.github.com/repos/hypertable/hypertable/issues/13","id":70433130,"user":{"login":"nuggetwheat","id":11298,"avatar_url":"https://avatars.githubusercontent.com/u/11298?v=3","gravatar_id":"","url":"https://api.github.com/users/nuggetwheat","html_url":"https://github.com/nuggetwheat","followers_url":"https://api.github.com/users/nuggetwheat/followers","following_url":"https://api.github.com/users/nuggetwheat/following{/other_user}","gists_url":"https://api.github.com/users/nuggetwheat/gists{/gist_id}","starred_url":"https://api.github.com/users/nuggetwheat/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/nuggetwheat/subscriptions","organizations_url":"https://api.github.com/users/nuggetwheat/orgs","repos_url":"https://api.github.com/users/nuggetwheat/repos","events_url":"https://api.github.com/users/nuggetwheat/events{/privacy}","received_events_url":"https://api.github.com/users/nuggetwheat/received_events","type":"User","site_admin":false},"created_at":"2015-01-18T23:59:49Z","updated_at":"2015-01-18T23:59:49Z","body":"tail of master log:\r\n\r\n<pre>\r\n1421624962 INFO Hypertable.Master : (/home/doug/src/hypertable/src/cc/Hypertable/Master/OperationRelinquishAcknowledge.cc:87) Leaving RelinquishAcknowledge-168 2[0057855..0060088] from rs1\r\n1421624962 INFO Hypertable.Master : (/home/doug/src/hypertable/src/cc/Hypertable/Master/OperationMoveRange.cc:137) MoveRange 2[0082050..0083674]: destination is rs3 (previous: )\r\n1421624962 INFO Hypertable.Master : (/home/doug/src/hypertable/src/cc/Hypertable/Master/OperationMoveRange.cc:269) Leaving MoveRange-128 2[0044089..0046931] -> rs3\r\n1421624962 INFO Hypertable.Master : (/home/doug/src/hypertable/src/cc/Hypertable/Master/BalancePlanAuthority.cc:603) balance_move_complete for {TableIdentifier: id='2' generation=1421624940153017000} {RangeSpec: start='0020744' end='0023180'}\r\n1421624962 INFO Hypertable.Master : (/home/doug/src/hypertable/src/cc/Hypertable/Master/OperationRelinquishAcknowledge.cc:61) Entering RelinquishAcknowledge-169 2[0096831..??] source=rs1 state=INITIAL\r\n1421624962 INFO Hypertable.Master : (/home/doug/src/hypertable/src/cc/Hypertable/Master/OperationRelinquishAcknowledge.cc:87) Leaving RelinquishAcknowledge-169 2[0096831..??] from rs1\r\n1421624962 INFO Hypertable.Master : (/home/doug/src/hypertable/src/cc/Hypertable/Master/OperationMoveRange.cc:137) MoveRange 2[0042668..0044089]: destination is rs1 (previous: )\r\n1421624962 INFO Hypertable.Master : (/home/doug/src/hypertable/src/cc/Hypertable/Master/OperationMoveRange.cc:121) Entering MoveRange-170 2[0056066..0057855] state=INITIAL\r\n</pre>"}}