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.

Sign up for GitHub

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

Jump to bottom

Error when running "ls /tmp/spotifile/playlists/music" #53

Open
jasonhansel opened this issue Jan 5, 2017 · 3 comments
Open

Error when running "ls /tmp/spotifile/playlists/music" #53

jasonhansel opened this issue Jan 5, 2017 · 3 comments
Labels
bug

Comments

@jasonhansel
Copy link

jasonhansel commented Jan 5, 2017 •
edited
Loading

When I mount spotifile (with spotifile -d /tmp/spotifile) and then try to get the list of playlists (with ls /tmp/spotifile/playlists/music), spotifile aborts with an error message (included at the end of this post).

Some notes about my setup:

  • I have a very large number of playlists (probably several hundred), arranged in folders. I suspect that I may be hitting some sort of timeout because of the large number of playlists (especially because spotifile doesn't yet support playlist folders).
  • Sometimes, two playlists have the same name, but are in different folders.
  • Some of my playlists contain local files.
  • The bug occurs about 90% of the time. Sometimes, the "ls" command works, but any subsequent "ls" command (eg ls /tmp/spotifile/playlists/music/Summer, where Summer is the name of a playlist) will result in a similar error.
  • I'm using spotifile on Arch Linux via the AUR package.

Thanks for looking at this, if you have the time, and please tell me if I can provide any further information.

The full spotifile -d output is:

FUSE library version: 2.9.7
nullpath_ok: 1
nopath: 1
utime_omit_ok: 0
unique: 1, opcode: INIT (26), nodeid: 0, insize: 56, pid: 0
INIT: 7.25
flags=0x0007fffb
max_readahead=0x00020000
[D @ 2017-01-05 15:31:44 EST] spotifile: created root
[D @ 2017-01-05 15:31:44 EST] spotifile: created file connection
[D @ 2017-01-05 15:31:44 EST] spotifile: added connection to dir root
[D @ 2017-01-05 15:31:44 EST] spotifile: created dir browse
[D @ 2017-01-05 15:31:44 EST] spotifile: created dir artists
[D @ 2017-01-05 15:31:44 EST] spotifile: added artists to dir browse
[D @ 2017-01-05 15:31:44 EST] spotifile: created dir tracks
[D @ 2017-01-05 15:31:44 EST] spotifile: added tracks to dir browse
[D @ 2017-01-05 15:31:44 EST] spotifile: created dir albums
[D @ 2017-01-05 15:31:44 EST] spotifile: added albums to dir browse
[D @ 2017-01-05 15:31:44 EST] spotifile: added browse to dir root
[D @ 2017-01-05 15:31:44 EST] spotifile: created dir search
[D @ 2017-01-05 15:31:44 EST] spotifile: added search to dir root
[D @ 2017-01-05 15:31:44 EST] spotifile: created dir playlists
[D @ 2017-01-05 15:31:44 EST] spotifile: added playlists to dir root
[D @ 2017-01-05 15:31:44 EST] spotifile: created dir meta
[D @ 2017-01-05 15:31:44 EST] spotifile: added meta to dir playlists
[D @ 2017-01-05 15:31:44 EST] spotifile: created dir music
[D @ 2017-01-05 15:31:44 EST] spotifile: added music to dir playlists
[M @ 2017-01-05 15:31:44 EST] spotifile: spotifile initialising ...
[M @ 2017-01-05 15:31:44 EST] spotifile: spotify session created!
[M @ 2017-01-05 15:31:44 EST] spotifile: trying to login as DennisFile
[M @ 2017-01-05 15:31:44 EST] spotifile: spotify: 20:31:44.401 I [ap:1752] Connecting to AP ap.spotify.com:4070
[D @ 2017-01-05 15:31:44 EST] spotifile: spotify session processing thread: started
[M @ 2017-01-05 15:31:44 EST] spotifile: spotifile initialised
   INIT: 7.19
   flags=0x00000011
   max_readahead=0x00020000
   max_write=0x00020000
   max_background=0
   congestion_threshold=0
   unique: 1, success, outsize: 40
[M @ 2017-01-05 15:31:44 EST] spotifile: spotify: logged in
unique: 2, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 3913
getattr /
   unique: 2, success, outsize: 120
[M @ 2017-01-05 15:31:44 EST] spotifile: spotify: 20:31:44.426 I [ap:1226] Connected to AP: 193.235.32.34:4070
unique: 3, opcode: LOOKUP (1), nodeid: 1, insize: 50, pid: 1324
LOOKUP /playlists
getattr /playlists
   NODEID: 2
   unique: 3, success, outsize: 144
unique: 4, opcode: LOOKUP (1), nodeid: 2, insize: 46, pid: 1324
LOOKUP /playlists/music
getattr /playlists/music
   NODEID: 3
   unique: 4, success, outsize: 144
unique: 5, opcode: LOOKUP (1), nodeid: 1, insize: 50, pid: 1324
LOOKUP /playlists
getattr /playlists
   NODEID: 2
   unique: 5, success, outsize: 144
unique: 6, opcode: LOOKUP (1), nodeid: 2, insize: 46, pid: 1324
LOOKUP /playlists/music
getattr /playlists/music
   NODEID: 3
   unique: 6, success, outsize: 144
unique: 7, opcode: OPENDIR (27), nodeid: 3, insize: 48, pid: 1324
opendir flags: 0x18800 /playlists/music
   opendir[140356914001696] flags: 0x18800 /playlists/music
   unique: 7, success, outsize: 32
unique: 8, opcode: READDIR (28), nodeid: 3, insize: 80, pid: 1324
readdir[140356914001696] from 0
[D @ 2017-01-05 15:31:48 EST] spotifile: filling existing dir (null) 
[D @ 2017-01-05 15:31:48 EST] spotifile: waiting for playlist to load
Attempt to unlock mutex that was not locked

Moreover, the following stack trace gets printed to the system journal:

Process 1309 (spotifile) of user 1000 dumped core.

Stack trace of thread 1321:
#0  0x00007fa769d4304f raise (libc.so.6)
#1  0x00007fa769d4447a abort (libc.so.6)
#2  0x00007fa76a5984fd n/a (libglib-2.0.so.0)
#3  0x0000000000407d1a n/a (spotifile)
#4  0x00007fa76a57b0d5 n/a (libglib-2.0.so.0)
#5  0x00007fa76a0b5454 start_thread (libpthread.so.0)
#6  0x00007fa769df87df __clone (libc.so.6)

Stack trace of thread 1313:
#0  0x00007fa76a0be1cd read (libpthread.so.0)
#1  0x00007fa76a2de092 n/a (libfuse.so.2)
#2  0x00007fa76a2dfc09 n/a (libfuse.so.2)
#3  0x00007fa76a2de6be n/a (libfuse.so.2)
#4  0x00007fa76a0b5454 start_thread (libpthread.so.0)
#5  0x00007fa769df87df __clone (libc.so.6)

Stack trace of thread 1315:
#0  0x00007fa76a0bd4f7 do_futex_wait.constprop.1 (libpthread.so.0)
#1  0x00007fa76a0bd5a4 __new_sem_wait_slow.constprop.0 (libpthread.so.0)
#2  0x00007fa76a9111f8 n/a (libspotify.so.12)
#3  0x00007fa76a8cb08d n/a (libspotify.so.12)
#4  0x00007fa76a0b5454 start_thread (libpthread.so.0)
#5  0x00007fa769df87df __clone (libc.so.6)

Stack trace of thread 1309:
#0  0x00007fa76a0bd4f7 do_futex_wait.constprop.1 (libpthread.so.0)
#1  0x00007fa76a0bd5a4 __new_sem_wait_slow.constprop.0 (libpthread.so.0)
#2  0x00007fa76a2de928 fuse_session_loop_mt (libfuse.so.2)
#3  0x00007fa76a2e4047 fuse_loop_mt (libfuse.so.2)
#4  0x00007fa76a2e6d4d n/a (libfuse.so.2)
#5  0x0000000000403fcb n/a (spotifile)
#6  0x00007fa769d30291 __libc_start_main (libc.so.6)
#7  0x00000000004042aa n/a (spotifile)

Stack trace of thread 1314:
#0  0x00007fa769df3f19 syscall (libc.so.6)
#1  0x00007fa76a59903a g_cond_wait_until (libglib-2.0.so.0)
#2  0x0000000000408295 n/a (spotifile)
#3  0x00000000004094da n/a (spotifile)
#4  0x0000000000406b04 n/a (spotifile)
#5  0x0000000000404f92 n/a (spotifile)
#6  0x00007fa76a2d9c52 fuse_fs_readdir (libfuse.so.2)
#7  0x00007fa76a2d9ddc n/a (libfuse.so.2)
#8  0x00007fa76a2e0996 n/a (libfuse.so.2)
#9  0x00007fa76a2e1f91 n/a (libfuse.so.2)
#10 0x00007fa76a2de738 n/a (libfuse.so.2)
#11 0x00007fa76a0b5454 start_thread (libpthread.so.0)
#12 0x00007fa769df87df __clone (libc.so.6)

Stack trace of thread 1316:
#0  0x00007fa769def48d poll (libc.so.6)
#1  0x00007fa76a991317 n/a (libspotify.so.12)
#2  0x00007fa76a99178d n/a (libspotify.so.12)
#3  0x00007fa76a8cb08d n/a (libspotify.so.12)
#4  0x00007fa76a0b5454 start_thread (libpthread.so.0)
#5  0x00007fa769df87df __clone (libc.so.6)
@catharsis
Copy link
Owner

Without looking too closely, I'm guessing this is related to the somewhat naive callback timeout defined here:

spotifile/src/spotify-fs.h

Line 16 in 03cff65

#define SPFS_CB_TIMEOUT_S 30

The error handling in case of callback timeouts is not very good at all, so as a first attempt, I'd suggest increasing that and recompiling.

@catharsis catharsis added the bug label Jan 17, 2017
@jasonhansel
Copy link
Author

I had a chance to try changing the timeout to 60000. This time, when I run ls /tmp/spotifile/playlists/music, spotifile -d hangs after several minutes with the output included below. The ChannelError messages appear to be unimportant cache misses, as described here.

[D @ 2017-01-22 19:40:09 EST] spotifile: created root
[D @ 2017-01-22 19:40:09 EST] spotifile: created file connection
[D @ 2017-01-22 19:40:09 EST] spotifile: added connection to dir root
[D @ 2017-01-22 19:40:09 EST] spotifile: created dir browse
[D @ 2017-01-22 19:40:09 EST] spotifile: created dir artists
[D @ 2017-01-22 19:40:09 EST] spotifile: added artists to dir browse
[D @ 2017-01-22 19:40:09 EST] spotifile: created dir tracks
[D @ 2017-01-22 19:40:09 EST] spotifile: added tracks to dir browse
[D @ 2017-01-22 19:40:09 EST] spotifile: created dir albums
[D @ 2017-01-22 19:40:09 EST] spotifile: added albums to dir browse
[D @ 2017-01-22 19:40:09 EST] spotifile: added browse to dir root
[D @ 2017-01-22 19:40:09 EST] spotifile: created dir search
[D @ 2017-01-22 19:40:09 EST] spotifile: added search to dir root
[D @ 2017-01-22 19:40:09 EST] spotifile: created dir playlists
[D @ 2017-01-22 19:40:09 EST] spotifile: added playlists to dir root
[D @ 2017-01-22 19:40:09 EST] spotifile: created dir meta
[D @ 2017-01-22 19:40:09 EST] spotifile: added meta to dir playlists
[D @ 2017-01-22 19:40:09 EST] spotifile: created dir music
[D @ 2017-01-22 19:40:09 EST] spotifile: added music to dir playlists
[M @ 2017-01-22 19:40:09 EST] spotifile: spotifile initialising ...
[M @ 2017-01-22 19:40:09 EST] spotifile: spotify session created!
[M @ 2017-01-22 19:40:09 EST] spotifile: trying to login as DennisFile
[M @ 2017-01-22 19:40:09 EST] spotifile: spotifile initialised
[M @ 2017-01-22 19:40:09 EST] spotifile: spotify: 00:40:09.453 I [ap:1752] Connecting to AP ap.spotify.com:4070
[D @ 2017-01-22 19:40:09 EST] spotifile: spotify session processing thread: started
[M @ 2017-01-22 19:40:09 EST] spotifile: spotify: logged in
[M @ 2017-01-22 19:40:09 EST] spotifile: spotify: 00:40:09.475 I [ap:1226] Connected to AP: 23.92.108.84:4070
[D @ 2017-01-22 19:40:12 EST] spotifile: filling existing dir /playlists/music 
[D @ 2017-01-22 19:40:12 EST] spotifile: waiting for playlist to load
[D @ 2017-01-22 19:40:12 EST] spotifile: waiting for playlist to load
[M @ 2017-01-22 19:40:12 EST] spotifile: spotify: 00:40:12.931 E [ap:4172] ChannelError(3, 0, playlist)
[M @ 2017-01-22 19:40:12 EST] spotifile: spotify: 00:40:12.931 E [ap:4172] ChannelError(4, 1, link-tracks)
[M @ 2017-01-22 19:40:13 EST] spotifile: spotify: 00:40:13.199 E [ap:4172] ChannelError(4, 1, link-tracks)
[M @ 2017-01-22 19:40:13 EST] spotifile: spotify: 00:40:13.503 E [ap:4172] ChannelError(0, 1, link-tracks)
[M @ 2017-01-22 19:40:13 EST] spotifile: spotify: 00:40:13.815 E [ap:4172] ChannelError(0, 1, link-tracks)
[M @ 2017-01-22 19:40:19 EST] spotifile: spotify: 00:40:19.876 E [ap:4172] ChannelError(233, 1, playlist)
[M @ 2017-01-22 19:40:19 EST] spotifile: spotify: 00:40:19.894 E [ap:4172] ChannelError(234, 1, playlist)
[M @ 2017-01-22 19:40:25 EST] spotifile: spotify: 00:40:25.006 E [ap:4172] ChannelError(0, 0, playlist)
[M @ 2017-01-22 19:40:30 EST] spotifile: spotify: 00:40:30.112 E [ap:4172] ChannelError(1, 1, playlist)
[M @ 2017-01-22 19:40:39 EST] spotifile: spotify: 00:40:39.614 E [ap:4172] ChannelError(0, 1, playlist)
[M @ 2017-01-22 19:40:44 EST] spotifile: spotify: 00:40:44.719 E [ap:4172] ChannelError(1, 1, playlist)
[M @ 2017-01-22 19:40:44 EST] spotifile: spotify: 00:40:44.737 E [ap:4172] ChannelError(0, 0, playlist)
[M @ 2017-01-22 19:40:54 EST] spotifile: spotify: 00:40:54.967 E [ap:4172] ChannelError(0, 1, playlist)
[M @ 2017-01-22 19:41:15 EST] spotifile: spotify: 00:41:15.083 E [ap:4172] ChannelError(0, 0, playlist)
[M @ 2017-01-22 19:41:32 EST] spotifile: spotify: 00:41:32.569 E [ap:4172] ChannelError(1, 1, playlist)
[M @ 2017-01-22 19:41:32 EST] spotifile: spotify: 00:41:32.778 E [ap:4172] ChannelError(0, 1, playlist)
[M @ 2017-01-22 19:42:07 EST] spotifile: spotify: 00:42:07.898 E [ap:4172] ChannelError(0, 0, playlist)
[M @ 2017-01-22 19:42:48 EST] spotifile: spotify: 00:42:48.043 E [ap:4172] ChannelError(1, 1, playlist)
[M @ 2017-01-22 19:42:49 EST] spotifile: spotify: 00:42:49.339 E [ap:4172] ChannelError(0, 1, playlist)
[M @ 2017-01-22 19:44:24 EST] spotifile: spotify: 00:44:24.777 E [ap:4172] ChannelError(0, 0, playlist)
[M @ 2017-01-22 19:44:29 EST] spotifile: spotify: 00:44:29.935 E [ap:4172] ChannelError(0, 1, playlist)
[M @ 2017-01-22 19:44:40 EST] spotifile: spotify: 00:44:40.171 E [ap:4172] ChannelError(0, 1, playlist)
[M @ 2017-01-22 19:47:40 EST] spotifile: spotify: 00:47:40.392 E [ap:4172] ChannelError(0, 0, playlist)
[M @ 2017-01-22 19:49:10 EST] spotifile: spotify: 00:49:10.573 E [ap:4172] ChannelError(0, 1, playlist)
[M @ 2017-01-22 19:49:40 EST] spotifile: spotify: 00:49:40.685 E [ap:4172] ChannelError(0, 1, playlist)
[M @ 2017-01-22 19:54:35 EST] spotifile: spotify: 00:54:35.933 E [ap:4172] ChannelError(0, 0, playlist)
[M @ 2017-01-22 19:56:36 EST] spotifile: spotify: 00:56:36.145 E [ap:4172] ChannelError(0, 1, playlist)
[M @ 2017-01-22 19:56:36 EST] spotifile: spotify: 00:56:36.163 E [ap:4172] ChannelError(1, 1, playlist)

@isovector
Copy link

I can reproduce this using spotifile 0.1.7-2 from AUR.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@catharsis @isovector @jasonhansel