Skip to content
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.

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

Nicotine+ 3.3.1 crash on tuple index out of range #2907

Closed
501NotImplemented opened this issue Feb 29, 2024 · 25 comments
Closed

Nicotine+ 3.3.1 crash on tuple index out of range #2907

501NotImplemented opened this issue Feb 29, 2024 · 25 comments

Comments

@501NotImplemented
Copy link

501NotImplemented commented Feb 29, 2024

Nicotine+ Version: 3.3.1
Operating System/Distribution:
Nicotine+ Version: 3.3.1
GTK Version: 4.12.5
Python Version: 3.11.8 (win32)
OS: Windows 11 Pro
Version 23H2
OS build 22631.3155
Experience Windows Feature Experience Pack 1000.22684.1000.0

Describe the bug

Nicotine+ crashes randomly

Expected behavior

The app should not crash and continue execution.

Steps to reproduce the bug

No particular, the app crashes at some point.
From the log, it might be related to file rescan issues (see screenshot).

Type: <class 'IndexError'>
Value: tuple index out of range
Traceback: File "D:/a/nicotine-plus/nicotine-plus/pynicotine/gtkgui/application.py", line 961, in on_process_thread_events
File "D:/a/nicotine-plus/nicotine-plus/pynicotine/events.py", line 290, in process_thread_events
File "D:/a/nicotine-plus/nicotine-plus/pynicotine/events.py", line 246, in emit
File "D:/a/nicotine-plus/nicotine-plus/pynicotine/search.py", line 435, in _file_search_request_distributed
File "D:/a/nicotine-plus/nicotine-plus/pynicotine/search.py", line 688, in _process_search_request
File "D:/a/nicotine-plus/nicotine-plus/pynicotine/search.py", line 474, in _create_file_info_list

@slook
Copy link
Member

slook commented Feb 29, 2024

Possible regression since 67d84e5

Please can you email the problematic files with invalid headers to the email address on @mathiascode 's GitHub profile.

@mathiascode
Copy link
Member

e8b8a91 makes scanning actually fail.

@501NotImplemented Can you try the latest unstable build? It should provide a more detailed error message.
https://nicotine-plus.org/doc/TESTING.html#windows

@501NotImplemented
Copy link
Author

501NotImplemented commented Feb 29, 2024

@mathiascode I've upgraded to 3.3.2, the issue did not reproduce for now.
I'll also share the problematic files with you via email.

@501NotImplemented
Copy link
Author

Okay, I've caught it on 3.3.2 after enabling rescan shares on the startup option. Will try the latest testing build as well.

Nicotine+ Version: 3.3.2
GTK Version: 4.12.5
Python Version: 3.11.8 (win32)

Type: <class 'IndexError'> Value: tuple index out of range Traceback: File "D:/a/nicotine-plus/nicotine-plus/pynicotine/gtkgui/application.py", line 961, in on_process_thread_events File "D:/a/nicotine-plus/nicotine-plus/pynicotine/events.py", line 290, in process_thread_events File "D:/a/nicotine-plus/nicotine-plus/pynicotine/events.py", line 246, in emit File "D:/a/nicotine-plus/nicotine-plus/pynicotine/search.py", line 435, in _file_search_request_distributed File "D:/a/nicotine-plus/nicotine-plus/pynicotine/search.py", line 688, in _process_search_request File "D:/a/nicotine-plus/nicotine-plus/pynicotine/search.py", line 474, in _create_file_info_list

Here's also the content of debug log file:

29.02.2024 23:24:13 Loading Python 3.11.8
29.02.2024 23:24:13 Loading Nicotine+ 3.3.2
29.02.2024 23:24:13 Faulthandler module could not be enabled. Error: sys.stderr is None
29.02.2024 23:24:13 Loading GTK 4.12.5
29.02.2024 23:24:13 Loading plugin system
29.02.2024 23:24:13 Loaded plugin Nicotine+ Commands
29.02.2024 23:24:13 Leech Detector: Require users have a minimum of 1 files in 1 shared public folders.
29.02.2024 23:24:13 Loaded plugin Leech Detector
29.02.2024 23:24:13 Loaded plugin Auto-Browse Shares
29.02.2024 23:24:13 Listening on port: 2234
29.02.2024 23:24:13 Connecting to server.slsknet.org:2242
29.02.2024 23:24:13 Connected to server server.slsknet.org:2242, logging in…
29.02.2024 23:24:14 UPnP: Failed to forward external port 2234: HTTP Error 500: Internal Server Error
29.02.2024 23:24:15 1983 privileged users
29.02.2024 23:24:15 You have no Soulseek privileges. While privileges are active, your downloads will be queued ahead of those of non-privileged users.

@slook
Copy link
Member

slook commented Mar 1, 2024

You can enable the "Search" and "Miscellaneous" debug logging catagories for more detailed information.

What we know so far is that the crash is triggered at the moment the client prepares to serve an incoming search request using faulty shares data arising from an invalid Flac header.

@mathiascode
Copy link
Member

The files you sent are corrupted. None of them play, and one is full of null bytes.

What we know so far is that the crash is triggered at the moment the client prepares to serve an incoming search request using faulty shares data arising from an invalid Flac header.

This isn't completely right. The screenshot says there was an issue saving the database at the end of the rescan process. Due to an additional try except, the scanner didn't catch this, assumed the scan finished successfully, and enabled search request processing with invalid/previous data.

The invalid files shouldn't be causing this issue, the scanner will just skip setting metadata for them.

@501NotImplemented Can you try a rescan in the testing build, and see if it fails again and shows more details about the issue?

@501NotImplemented
Copy link
Author

@mathiascode I've sent you debug logs from the client Nicotine+ 3.3.3.dev1. Please check your mail.
The client crashed several times silently when I've just opened the Uploads tab. If I can provide any other logs or useful info - please let me know.

One log line that brought to my attention:
01.03.2024 19:15:32 Failed to fetch the shared folder To listen\France\Kromozom 4 - 2019 Hardcore Fun - À Boire Et À Manger (Et D'Autres Vieux Trucs Dedans): argument of type 'NoneType' is not iterable

@slook
Copy link
Member

slook commented Mar 1, 2024

the scanner will just skip setting metadata for them

The None value should be an empty set().

Open a private chat to yourself (or it can be any chat entry) and enter the command /rescan rebuild. This will force a full scan to create the databases from scratch, then the error caused by the bug in the previous version, should be cleared.

Alternatively, simply delete all the .dbn files that will result in doing the same thing.

@mathiascode
Copy link
Member

@mathiascode I've sent you debug logs from the client Nicotine+ 3.3.3.dev1. Please check your mail. The client crashed several times silently when I've just opened the Uploads tab. If I can provide any other logs or useful info - please let me know.

Unfortunately, it looks like rescanning succeeded this time, so I have no idea what caused it to fail before.

Is the Uploads tab issue unrelated to this one? By silent crash, do you mean the window just closes when opening the Uploads tab?

One log line that brought to my attention: 01.03.2024 19:15:32 Failed to fetch the shared folder To listen\France\Kromozom 4 - 2019 Hardcore Fun - À Boire Et À Manger (Et D'Autres Vieux Trucs Dedans): argument of type 'NoneType' is not iterable

Was this before the most recent rescan?

@mathiascode
Copy link
Member

the scanner will just skip setting metadata for them

The None value should be an empty set().

What are you talking about? What part of the code?

@501NotImplemented
Copy link
Author

501NotImplemented commented Mar 1, 2024

@mathiascode yes, that particular message was before the most recent rescan.

For now - I've deleted the corrupted files from the drive.
Delete the folder, where those corrupted files were located from shared list
Deleted the .dbn files from the AppData\Roaming\nicotine
Forced the rescan, it successfully completed from the logs.

01.03.2024 20:30:21 Rebuilding shares… 01.03.2024 20:30:50 Rescan complete: 23328 folders found

As of this moment - I am able to browse my files again, and the Nicotine+ does not crash. But it shows 0 files and 0 folders shared for me. In User Profile and Buddy list. Does it take some time to show the correct value?

I've shared the folder again and forced a rescan from private chat as @slook suggested.
01.03.2024 20:58:46 Rebuilding shares… 01.03.2024 20:59:26 Rescan complete: 30553 folders found

Still 0 files shared is shown on UI in User Profile and Buddy lis, but I see new Uploads are starting and running and I still can browse myself and see the files in the Browse Shares.

UPD: After the app restart - it still shows 0, the new Uploads are active.

@slook
Copy link
Member

slook commented Mar 1, 2024

Still 0 files shared is shown on UI in User Profile

That is the value reported by the server, which takes a while to update. Edit: No, I'm wrong about that, the data is supposed to come from a "user-stats" event, but it perhaps doesn't occur if the client had already created that event before counting the shares. ... Hopefully fixed in PR #2915

The None value should be an empty set().

What are you talking about? What part of the code?

I don't know, I was mistaken...

For now - I've deleted the corrupted files from the drive.

For testing purposes, you could add them again to verify that the scanner should now skip them gracefully, with a logged error about invalid metadata during the rescan?

@slook
Copy link
Member

slook commented Mar 3, 2024

@501NotImplemented what is the status of this bug? Is it fixed now or are we not able to establish the exact cause?

@501NotImplemented
Copy link
Author

@slook I've put the corrupted files into a separate directory, added it to the shares and saved Nicorine configuration.
Share rescan started immediately.
03.03.2024 16:37:05 Rescanning shares…

I see scanning shares spinner in the app tray and it seems like the process is stuck. The Nicotine+ 3.3.3.dev1 is working for now.

Restarted the app.
03.03.2024 16:42:01 Rebuilding shares…
Same, scanning shares spinner spins, the process does not end. However, the app does not crash for now.

@slook
Copy link
Member

slook commented Mar 3, 2024

Alright, if and when it does finish please report the timestamp of the "Rebuild complete: X folders found" log message to establish the number of minutes that elapsed since the "03.03.2024 16:42:01 Rebuilding shares…" message, along with any other scanning errors printed into the log.

the process does not end. However, the app does not crash for now.

The idea is that the application window shouldn't be interrupted by the scanner process, so please verify that it does not hang or crash, but if it is taking an inordinately long time then that might indicate some problem is happening.

@slook slook added this to the 3.3.3 milestone Mar 3, 2024
@501NotImplemented
Copy link
Author

@slook the app crashed after some time of running in background.

After the restart:
03.03.2024 18:18:05 Rescanning shares…
03.03.2024 18:18:07 [Misc] Saved configuration: C:\Users*****\AppData\Roaming\nicotine\config\config
03.03.2024 18:18:25 Rescan complete: 32243 folders found

@slook
Copy link
Member

slook commented Mar 3, 2024

the app crashed

How did you realise this? Did it crash silently without error message?

@501NotImplemented
Copy link
Author

501NotImplemented commented Mar 3, 2024

@slook Yes, exactly. I've had it running in the background, went away from PC for some time, and after I returned - it wasn't running. Had to restart it manually.

@slook
Copy link
Member

slook commented Mar 3, 2024

Whilst the original "tuple index out of range IndexError" caused by the bug in 3.3.1 and 3.3.2 has been fixed in 3.3.3dev1, it appears that a further mitigation is ideally required, but there is a lack of any debug logging or other details to define this, and nobody else has reported a similar crash yet.

@mathiascode Suggest bump to 3.3.3dev2 to help us more easily identify stack traces since e8b8a91 was applied.

Please continue to report any further issues with the nightly unstable development builds , at link:
https://github.com/nicotine-plus/nicotine-plus/blob/master/doc/TESTING.md#windows

Closing as resolved, at least the problem that leads to the original crash will be avoided.

@501NotImplemented
Copy link
Author

@slook looks like this issue has to be reopened.

Nicotine+ Version: 3.3.3.dev2
GTK Version: 4.12.5
Python Version: 3.11.8 (win32)

Type: <class 'IndexError'>
Value: tuple index out of range
Traceback: File "D:/a/nicotine-plus/nicotine-plus/pynicotine/gtkgui/application.py", line 961, in on_process_thread_events
File "D:/a/nicotine-plus/nicotine-plus/pynicotine/events.py", line 290, in process_thread_events
File "D:/a/nicotine-plus/nicotine-plus/pynicotine/events.py", line 246, in emit
File "D:/a/nicotine-plus/nicotine-plus/pynicotine/search.py", line 434, in _file_search_request_distributed
File "D:/a/nicotine-plus/nicotine-plus/pynicotine/search.py", line 687, in _process_search_request
File "D:/a/nicotine-plus/nicotine-plus/pynicotine/search.py", line 473, in _create_file_info_list

That's the only log that is available, unfortunately.

@mathiascode mathiascode reopened this Mar 7, 2024
@mathiascode
Copy link
Member

Could you send your .dbn files again?

I don't know what else to do at this point. None of the errors make any sense, and I haven't been able to reproduce any of them.

@501NotImplemented
Copy link
Author

@mathiascode yes, please check your email.

@slook slook removed the bug label Mar 20, 2024
@mathiascode mathiascode removed this from the 3.3.3 milestone Mar 27, 2024
@slook
Copy link
Member

slook commented Apr 1, 2024

Closing this as sadly there is nothing actionable we can do to identify what the quirk is on the affected machine which leads to the spurious errors thrown by the Python interpreter.

@slook slook closed this as not planned Won't fix, can't repro, duplicate, stale Apr 1, 2024
@slook slook removed the invalid label Apr 2, 2024
@slook
Copy link
Member

slook commented Apr 2, 2024

This issue isn't invalid because something useful did come out of this series of investigations, since e8b8a91 avoids a potential for corruption of the shares database in the exceptionally rare case of a fault, and the user did stumble upon an incidental bug before it was later reported in issue #2956 that was fixed in PR #2915.

@slook slook closed this as completed Apr 2, 2024
@mathiascode
Copy link
Member

Fair enough.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

No branches or pull requests

3 participants