Ticket #28 (closed defect: fixed)

Opened 3 years ago

Last modified 3 years ago

Endless error loop if a shared file gets deleted during hashing

Reported by: chemical Assigned to: madcat
Priority: normal Milestone:
Component: hydraengine Version: svn-snapshot
Severity: blocker Keywords: hasher loop stuck error
Cc:

Description

The short summary says everything. Noticed in r1478 that the hasher thread falls into an endless loop of "Error: Unable to oben file: ....." and floods the console and hydranode.log if a shared file gets removed (perhaps while the hasher is accessing it?).

As I had the remove the log immediately I have nothing to paste here, sorry.

Change History

07/16/05 08:01:56 changed by chemical

Was able to reproduce it.

It appears to happen on a request of a client for a already removed (but hashed and offered) file:

[2005-Jul-16 10:25:55] [Statistics] Sources: 4096 | Queued: 1119 | Up: 9.96 KB/s | Down: 3.64 KB/s [2005-Jul-16 10:26:05] [Statistics] Sources: 4097 | Queued: 1121 | Up: 9.93 KB/s | Down: 3.14 KB/s [2005-Jul-16 10:26:15] [Statistics] Sources: 4096 | Queued: 1121 | Up: 9.92 KB/s | Down: 3.46 KB/s [2005-Jul-16 10:26:23] Debug: [212.100.47.173:4662] Error during client stream parsing/handling: clients.cpp:911: Check `m_uploadInfo' failed [2005-Jul-16 10:26:25] [Statistics] Sources: 4096 | Queued: 1119 | Up: 9.96 KB/s | Down: 3.34 KB/s [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Debug: [213.196.221.49:4662] Sending next chunk to ed2kclient: Error reading file x: modification date 3221218056 != 1121417042 [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Hasher reported fatal error. Removing shared file x [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing.

As you can see some lines above, hydranode hasher correctly removes the removed file from SharedFiles?, but the error loops until I kill the core.

The 'x' is a placeholder for ONE specific file here. Do you need more Debug information?

07/16/05 08:03:11 changed by chemical

Was able to reproduce it.

It appears to happen on a request of a client for a already removed (but hashed and offered) file:

[2005-Jul-16 10:25:55] [Statistics] Sources: 4096 | Queued: 1119 | Up: 9.96 KB/s | Down: 3.64 KB/s [2005-Jul-16 10:26:05] [Statistics] Sources: 4097 | Queued: 1121 | Up: 9.93 KB/s | Down: 3.14 KB/s [2005-Jul-16 10:26:15] [Statistics] Sources: 4096 | Queued: 1121 | Up: 9.92 KB/s | Down: 3.46 KB/s [2005-Jul-16 10:26:23] Debug: [212.100.47.173:4662] Error during client stream parsing/handling: clients.cpp:911: Check `m_uploadInfo' failed [2005-Jul-16 10:26:25] [Statistics] Sources: 4096 | Queued: 1119 | Up: 9.96 KB/s | Down: 3.34 KB/s [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Debug: [213.196.221.49:4662] Sending next chunk to ed2kclient: Error reading file x: modification date 3221218056 != 1121417042 [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Hasher reported fatal error. Removing shared file x [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing.

As you can see some lines above, hydranode hasher correctly removes the removed file from SharedFiles?, but the error loops until I kill the core.

The 'x' is a placeholder for ONE specific file here. Do you need more Debug information?

07/16/05 08:07:08 changed by chemical

Was able to reproduce it.

It appears to happen on a request of a client for a already removed (but hashed and offered) file:

{{{[2005-Jul-16 10:25:55] [Statistics] Sources: 4096 | Queued: 1119 | Up: 9.96 KB/s | Down: 3.64 KB/s [2005-Jul-16 10:26:05] [Statistics] Sources: 4097 | Queued: 1121 | Up: 9.93 KB/s | Down: 3.14 KB/s [2005-Jul-16 10:26:15] [Statistics] Sources: 4096 | Queued: 1121 | Up: 9.92 KB/s | Down: 3.46 KB/s [2005-Jul-16 10:26:23] Debug: [212.100.47.173:4662] Error during client stream parsing/handling: clients.cpp:911: Check `m_uploadInfo' failed [2005-Jul-16 10:26:25] [Statistics] Sources: 4096 | Queued: 1119 | Up: 9.96 KB/s | Down: 3.34 KB/s [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Debug: [213.196.221.49:4662] Sending next chunk to ed2kclient: Error reading file x: modification date 3221218056 != 1121417042 [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Hasher reported fatal error. Removing shared file x [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Warning: onSharedFileEvent: SharedFile? doesn't have MetaData?. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing. [2005-Jul-16 10:26:27] Error: Unable to open file `/donkey/incoming/x' for hashing.}}}

As you can see some lines above, hydranode hasher correctly removes the removed file from SharedFiles?, but the error loops until I kill the core.

The 'x' is a placeholder for ONE specific file here. Do you need more Debug information?

Sorry for multiple posts, the web interface had some hangups.

07/20/05 05:51:48 changed by madcat

  • status changed from new to closed.
  • resolution set to fixed.

Fixed in [1450].

07/20/05 05:52:46 changed by madcat

Sorry, fixed in [1540] that is.

07/23/05 04:57:11 changed by chemical <chem@gmx.net>

  • status changed from closed to reopened.
  • resolution deleted.

Sorry, it's not. It happened to me again with rev1559. 

[2005-Jul-23 00:55:35] Debug: Full hash complete:
[2005-Jul-23 00:55:35] Debug: FileName: /donkey/incoming/xxxxxxxx
[2005-Jul-23 00:55:35] Debug: FileSize: 22044344
[2005-Jul-23 00:55:35] Debug: ModDate:  1121985535
[2005-Jul-23 00:55:35] Debug: ED2KHash: be34a9232ff9673de916ff3685------
[2005-Jul-23 00:55:35] Debug: SHA1Hash: f1828d2ccd46a6adf8c7d3403da370a1b3------
[2005-Jul-23 00:55:35] Debug: MD4Hash: f4afced7d579f489026c71c7ca------
[2005-Jul-23 00:55:35] Debug: MD5Hash: fc46c19decd9beda0fd5261d90------
[2005-Jul-23 00:55:35] Error: Unable to open file `/donkey/incoming/yyyyyyyy.
[2005-Jul-23 00:55:35] Error: Unable to open file `/donkey/incoming/yyyyyyyy.
[2005-Jul-23 00:55:35] Error: Unable to open file `/donkey/incoming/yyyyyyyy.
[2005-Jul-23 00:55:36] Error: Unable to open file `/donkey/incoming/yyyyyyyy.
[2005-Jul-23 00:55:36] Error: Unable to open file `/donkey/incoming/yyyyyyyy.
[2005-Jul-23 00:55:36] Error: Unable to open file `/donkey/incoming/yyyyyyyy.
[2005-Jul-23 00:55:36] Error: Unable to open file `/donkey/incoming/yyyyyyyy.
[2005-Jul-23 00:55:36] Error: Unable to open file `/donkey/incoming/yyyyyyyy.
[2005-Jul-23 00:55:36] Error: Unable to open file `/donkey/incoming/yyyyyyyy.
[2005-Jul-23 00:55:36] Error: Unable to open file `/donkey/incoming/yyyyyyyy.
[2005-Jul-23 00:55:36] Error: Unable to open file `/donkey/incoming/yyyyyyyy.
[2005-Jul-23 00:55:36] Error: Unable to open file `/donkey/incoming/yyyyyyyy.
[2005-Jul-23 00:55:36] Debug: Offering file xxxxxxxx to server.
[2005-Jul-23 00:55:36] Error: Unable to open file `/donkey/incoming/yyyyyyyy.

xxxxxxxx and yyyyyyyy represent each a specific file. Right after finishing hashing the first file, it tries to continue on the second one (which isn't there anymore apparently). It got stuck in a loop printing that Error message.

07/23/05 04:58:46 changed by chemical <chem@gmx.net>

I just want to add that the core continued to work normal during that loop. It uploaded and downloaded just like before that loop.

07/23/05 11:20:12 changed by madcat

  • status changed from reopened to closed.
  • resolution set to fixed.

Fixed in [1560]