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

[jasonhansel]

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]

Without looking too closely, I'm guessing this is related to the somewhat naive callback timeout defined here: https://github.com/catharsis/spotifile/blob/03cff65b9972524af6d4b142924759777bd35cfc/src/spotify-fs.h#L16

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.

[jasonhansel]

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]

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