Bugzilla – Bug 12083
Browsing by Music Folder bug: empty Music Folders when browsing with Duet controller
Last modified: 2009-10-20 07:35:21 UTC
run latest nightly 7.3.3 on Ubuntu Jaunty. remote on version 5577. when browsing music folders, sometimes folders are shown as empty. Restart of the controller mostly fixes it. Sometimes going up a level or switching folders helps as well (not always). According to J Richardson should have been fixed in 5577 so asked to file a bug report. Thanks, Herman
what's your server hardware? Are these folders with many entries? The issue we've seen before is Controller running into a timeout if the server took too much time preparing the response.
Just saw the following line in the linked forum thread: "All music is stored on a DNS-323 NAS and mounted via NFS (earlier smb, had same issue)." This sounds like an awfully slow combination :-). Might very well be the timing issue.
server is a shuttle barebone with 4G mem and 8400 dual core 3GHz CPU. NAS is connected via gigabit with only a switch in between the boxes. Only delay I notice is if the disks on the NAS go in power safe which is when I notice the controller taking a couple of seconds more to respond (not fail). I have not seen any error messages in the logs. If there is anything I can do to provide more diagnostics then happy to do so. The reason I browse by music folder is because I have a sizeable music library. The behaviour is not just with folders that have many entries (sometimes just a few songs). It also happens irregularly ie I cannot relate it to the DNS323 power saving the disks as it also happens when I am browing from one folder to another...
> server is a shuttle barebone with 4G mem and 8400 dual core 3GHz CPU. This is where SC is running, and this machine has mounted the NAS share using NFS?
Yes. Just noticed an error in my earlier response: the mount is cifs, not nfs. Sorry for that: //dlink-1/Music on /media/disk type cifs (rw,mand,noexec,nosuid,nodev) the dlink-1 is the DNS-323 and SC scans /media/disk for music.
Can you turn the following logs to DEBUG, reproduce the error, then post the log here (network.cometd) - Cometd protocol loggin (scan.scanner) - Music & Playlist Folder Scanning
Here you go: browsed a couple of times in/out a folder )started with folder named trafassi, browsed a few others and then went back to trafassi and ... empty. debug log: [09-05-18 20:23:28.0013] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.4341, offset=1242493750.43407 [09-05-18 20:23:28.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43407, offset=1242493750.43462 [09-05-18 20:23:32.0013] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43407, offset=1242493750.43407 [09-05-18 20:23:32.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43407, offset=1242493750.43458 [09-05-18 20:23:36.0013] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43407, offset=1242493750.43407 [09-05-18 20:23:36.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43407, offset=1242493750.43456 [09-05-18 20:23:40.0014] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43407, offset=1242493750.43419 [09-05-18 20:23:40.0018] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43407, offset=1242493750.43471 [09-05-18 20:23:44.0013] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43407, offset=1242493750.43406 [09-05-18 20:23:44.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43406, offset=1242493750.43457 [09-05-18 20:23:48.0014] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43406, offset=1242493750.43414 [09-05-18 20:23:48.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43406, offset=1242493750.43465 [09-05-18 20:23:52.0013] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43406, offset=1242493750.43406 [09-05-18 20:23:52.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43406, offset=1242493750.43456 [09-05-18 20:23:56.0013] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43406, offset=1242493750.43409 [09-05-18 20:23:56.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43406, offset=1242493750.43461 [09-05-18 20:23:59.6582] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43406, offset=1242493750.435 [09-05-18 20:24:00.0654] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43406, offset=1242493750.43419 [09-05-18 20:24:00.0657] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43406, offset=1242493750.43464 [09-05-18 20:24:01.0010] Slim::Networking::Discovery::gotTLVRequest (156) discovery packet:"eIPAD\0NAME\0JSON\0" [09-05-18 20:24:01.0012] Slim::Networking::Discovery::gotTLVRequest (173) TLV: IPAD len: 0 [09-05-18 20:24:01.0013] Slim::Networking::Discovery::gotTLVRequest (173) TLV: NAME len: 0 [09-05-18 20:24:01.0015] Slim::Networking::Discovery::gotTLVRequest (173) TLV: JSON len: 0 [09-05-18 20:24:01.0017] Slim::Networking::Discovery::gotTLVRequest (194) sending response [09-05-18 20:24:01.0018] Slim::Networking::Discovery::Server::gotTLVResponse (161) discovery response packet: [09-05-18 20:24:01.0020] Slim::Networking::Discovery::Server::gotTLVResponse (177) TLV: NAME len: 9, egg-media [09-05-18 20:24:01.0022] Slim::Networking::Discovery::Server::gotTLVResponse (177) TLV: JSON len: 4, 9001 [09-05-18 20:24:01.0023] Slim::Networking::Discovery::Server::gotTLVResponse (197) Discovered server egg-media (192.168.1.102), using port 9001 [09-05-18 20:24:05.0014] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43406, offset=1242493750.43423 [09-05-18 20:24:05.0019] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43406, offset=1242493750.43473 [09-05-18 20:24:07.7433] Slim::Utils::Misc::findAndScanDirectoryTree (900) findAndScanDirectoryTree( /media/disk ): fsMTime: 1242557073, dbMTime: 1242557073 [09-05-18 20:24:11.0902] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43406, offset=1242493750.43398 [09-05-18 20:24:11.0905] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43398, offset=1242493750.43437 [09-05-18 20:24:12.7248] Slim::Utils::Misc::findAndScanDirectoryTree (900) findAndScanDirectoryTree( /media/disk ): fsMTime: 1242557073, dbMTime: 1242557073 [09-05-18 20:24:13.8887] Slim::Networking::Discovery::gotTLVRequest (156) discovery packet:"eIPAD\0NAME\0JSON\0JVID\6\x124Vx\x124" [09-05-18 20:24:13.8889] Slim::Networking::Discovery::gotTLVRequest (173) TLV: IPAD len: 0 [09-05-18 20:24:13.8891] Slim::Networking::Discovery::gotTLVRequest (173) TLV: NAME len: 0 [09-05-18 20:24:13.8892] Slim::Networking::Discovery::gotTLVRequest (173) TLV: JSON len: 0 [09-05-18 20:24:13.8894] Slim::Networking::Discovery::gotTLVRequest (173) TLV: JVID len: 6 [09-05-18 20:24:13.8896] Slim::Networking::Discovery::__ANON__ (119) Jive: 12:34:56:78:12:34 [09-05-18 20:24:13.8897] Slim::Networking::Discovery::gotTLVRequest (194) sending response [09-05-18 20:24:14.0709] Slim::Utils::Misc::findAndScanDirectoryTree (900) findAndScanDirectoryTree( /media/disk/Trafassi ): fsMTime: 1242557073, dbMTime: 1242557073 [09-05-18 20:24:16.0018] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43398, offset=1242493750.43454 [09-05-18 20:24:16.0021] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43398, offset=1242493750.43406 [09-05-18 20:24:18.2544] Slim::Utils::Misc::findAndScanDirectoryTree (900) findAndScanDirectoryTree( /media/disk/Tracy Chapman ): fsMTime: 1241594805, dbMTime: 1241594805 [09-05-18 20:24:20.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43398, offset=1242493750.43451 [09-05-18 20:24:20.0021] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43398, offset=1242493750.43405 [09-05-18 20:24:21.3095] Slim::Utils::Misc::findAndScanDirectoryTree (900) findAndScanDirectoryTree( /media/disk/Toy Box ): fsMTime: 1228176994, dbMTime: 1228176994 [09-05-18 20:24:22.8138] Slim::Utils::Misc::findAndScanDirectoryTree (900) findAndScanDirectoryTree( /media/disk/Toy Box/Fantastic ): fsMTime: 1231033272, dbMTime: 1231033272 [09-05-18 20:24:24.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43398, offset=1242493750.43444 [09-05-18 20:24:24.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43398, offset=1242493750.43394 [09-05-18 20:24:27.9453] Slim::Utils::Misc::findAndScanDirectoryTree (900) findAndScanDirectoryTree( /media/disk/Toto ): fsMTime: 1228176987, dbMTime: 1228176987 [09-05-18 20:24:28.0010] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43394, offset=1242493750.43388 [09-05-18 20:24:28.0014] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43388, offset=1242493750.43432 [09-05-18 20:24:29.5261] Slim::Utils::Misc::findAndScanDirectoryTree (900) findAndScanDirectoryTree( /media/disk/Toto/Past to Present 1977-1990 ): fsMTime: 1231033238, dbMTime: 1231033238 [09-05-18 20:24:32.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43388, offset=1242493750.43434 [09-05-18 20:24:32.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43388, offset=1242493750.43387 [09-05-18 20:24:35.9904] Slim::Utils::Misc::findAndScanDirectoryTree (900) findAndScanDirectoryTree( /media/disk/Total Touch ): fsMTime: 1241203730, dbMTime: 1241203730 [09-05-18 20:24:36.0432] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43387, offset=1242493750.45503 [09-05-18 20:24:36.0435] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43387, offset=1242493750.4554 [09-05-18 20:24:39.7488] Slim::Utils::Misc::findAndScanDirectoryTree (900) findAndScanDirectoryTree( /media/disk/Tori Amos ): fsMTime: 1241203730, dbMTime: 1241203730 [09-05-18 20:24:41.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43387, offset=1242493750.43447 [09-05-18 20:24:41.0021] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43387, offset=1242493750.43398 [09-05-18 20:24:45.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43387, offset=1242493750.43347 [09-05-18 20:24:45.0021] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43347, offset=1242493750.43401 [09-05-18 20:24:45.0563] Slim::Utils::Misc::findAndScanDirectoryTree (900) findAndScanDirectoryTree( /media/disk/Trafassi ): fsMTime: 1242557073, dbMTime: 1242557073 [09-05-18 20:24:49.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43347, offset=1242493750.43347 [09-05-18 20:24:49.0021] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43347, offset=1242493750.43398 [09-05-18 20:24:53.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43347, offset=1242493750.43347 [09-05-18 20:24:53.0021] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43347, offset=1242493750.43399 [09-05-18 20:24:57.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43347, offset=1242493750.43345 [09-05-18 20:24:57.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43345, offset=1242493750.43396 [09-05-18 20:25:00.0012] Slim::Networking::Discovery::gotTLVRequest (156) discovery packet:"eIPAD\0NAME\0JSON\0" [09-05-18 20:25:00.0014] Slim::Networking::Discovery::gotTLVRequest (173) TLV: IPAD len: 0 [09-05-18 20:25:00.0015] Slim::Networking::Discovery::gotTLVRequest (173) TLV: NAME len: 0 [09-05-18 20:25:00.0017] Slim::Networking::Discovery::gotTLVRequest (173) TLV: JSON len: 0 [09-05-18 20:25:00.0019] Slim::Networking::Discovery::gotTLVRequest (194) sending response [09-05-18 20:25:00.0020] Slim::Networking::Discovery::Server::gotTLVResponse (161) discovery response packet: [09-05-18 20:25:00.0022] Slim::Networking::Discovery::Server::gotTLVResponse (177) TLV: NAME len: 9, egg-media [09-05-18 20:25:00.0024] Slim::Networking::Discovery::Server::gotTLVResponse (177) TLV: JSON len: 4, 9001 [09-05-18 20:25:00.0025] Slim::Networking::Discovery::Server::gotTLVResponse (197) Discovered server egg-media (192.168.1.102), using port 9001 [09-05-18 20:25:01.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43345, offset=1242493750.43348 [09-05-18 20:25:01.0021] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43345, offset=1242493750.43401 [09-05-18 20:25:05.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43345, offset=1242493750.43345 [09-05-18 20:25:05.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43345, offset=1242493750.43395 [09-05-18 20:25:10.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43345, offset=1242493750.43346 [09-05-18 20:25:10.0021] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43345, offset=1242493750.434 [09-05-18 20:25:13.9638] Slim::Networking::Discovery::gotTLVRequest (156) discovery packet:"eIPAD\0NAME\0JSON\0JVID\6\x124Vx\x124" [09-05-18 20:25:13.9640] Slim::Networking::Discovery::gotTLVRequest (173) TLV: IPAD len: 0 [09-05-18 20:25:13.9642] Slim::Networking::Discovery::gotTLVRequest (173) TLV: NAME len: 0 [09-05-18 20:25:13.9644] Slim::Networking::Discovery::gotTLVRequest (173) TLV: JSON len: 0 [09-05-18 20:25:13.9645] Slim::Networking::Discovery::gotTLVRequest (173) TLV: JVID len: 6 [09-05-18 20:25:13.9647] Slim::Networking::Discovery::__ANON__ (119) Jive: 12:34:56:78:12:34 [09-05-18 20:25:13.9648] Slim::Networking::Discovery::gotTLVRequest (194) sending response [09-05-18 20:25:14.0010] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43345, offset=1242493750.4339 [09-05-18 20:25:14.0014] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43345, offset=1242493750.43332 [09-05-18 20:25:18.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43351 [09-05-18 20:25:18.0021] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43402 [09-05-18 20:25:23.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43344 [09-05-18 20:25:23.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43395 [09-05-18 20:25:27.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.4335 [09-05-18 20:25:27.0021] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43402 [09-05-18 20:25:31.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43342 [09-05-18 20:25:31.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43393 [09-05-18 20:25:35.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43342 [09-05-18 20:25:35.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43393 [09-05-18 20:25:40.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43339 [09-05-18 20:25:40.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43396 [09-05-18 20:25:44.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43344 [09-05-18 20:25:44.0021] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43397 [09-05-18 20:25:49.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43341 [09-05-18 20:25:49.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43393 [09-05-18 20:25:53.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43341 [09-05-18 20:25:53.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43393 [09-05-18 20:25:57.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43336 [09-05-18 20:25:57.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43387 [09-05-18 20:25:59.0011] Slim::Networking::Discovery::gotTLVRequest (156) discovery packet:"eIPAD\0NAME\0JSON\0" [09-05-18 20:25:59.0013] Slim::Networking::Discovery::gotTLVRequest (173) TLV: IPAD len: 0 [09-05-18 20:25:59.0014] Slim::Networking::Discovery::gotTLVRequest (173) TLV: NAME len: 0 [09-05-18 20:25:59.0016] Slim::Networking::Discovery::gotTLVRequest (173) TLV: JSON len: 0 [09-05-18 20:25:59.0018] Slim::Networking::Discovery::gotTLVRequest (194) sending response [09-05-18 20:25:59.0019] Slim::Networking::Discovery::Server::gotTLVResponse (161) discovery response packet: [09-05-18 20:25:59.0021] Slim::Networking::Discovery::Server::gotTLVResponse (177) TLV: NAME len: 9, egg-media [09-05-18 20:25:59.0023] Slim::Networking::Discovery::Server::gotTLVResponse (177) TLV: JSON len: 4, 9001 [09-05-18 20:25:59.0024] Slim::Networking::Discovery::Server::gotTLVResponse (197) Discovered server egg-media (192.168.1.102), using port 9001 [09-05-18 20:26:01.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43342 [09-05-18 20:26:01.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43396 [09-05-18 20:26:05.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43339 [09-05-18 20:26:05.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43392 [09-05-18 20:26:09.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43339 [09-05-18 20:26:09.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43389 [09-05-18 20:26:13.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.4334 [09-05-18 20:26:13.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.4339 [09-05-18 20:26:14.0739] Slim::Networking::Discovery::gotTLVRequest (156) discovery packet:"eIPAD\0NAME\0JSON\0JVID\6\x124Vx\x124" [09-05-18 20:26:14.0741] Slim::Networking::Discovery::gotTLVRequest (173) TLV: IPAD len: 0 [09-05-18 20:26:14.0743] Slim::Networking::Discovery::gotTLVRequest (173) TLV: NAME len: 0 [09-05-18 20:26:14.0744] Slim::Networking::Discovery::gotTLVRequest (173) TLV: JSON len: 0 [09-05-18 20:26:14.0746] Slim::Networking::Discovery::gotTLVRequest (173) TLV: JVID len: 6 [09-05-18 20:26:14.0748] Slim::Networking::Discovery::__ANON__ (119) Jive: 12:34:56:78:12:34 [09-05-18 20:26:14.0749] Slim::Networking::Discovery::gotTLVRequest (194) sending response [09-05-18 20:26:18.0017] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43343 [09-05-18 20:26:18.0021] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43396 [09-05-18 20:26:22.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43338 [09-05-18 20:26:22.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.4339 [09-05-18 20:26:26.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43338 [09-05-18 20:26:26.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43389 [09-05-18 20:26:31.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43336 [09-05-18 20:26:31.0020] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43387 [09-05-18 20:26:36.0012] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43332, offset=1242493750.43296 [09-05-18 20:26:36.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43296, offset=1242493750.43348 [09-05-18 20:26:40.0016] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43296, offset=1242493750.43334 [09-05-18 20:26:40.0019] Slim::Player::Player::trackJiffiesEpoch (920) 00:04:20:16:0c:fa trackJiffiesEpoch: epoch=1242493750.43296, offset=1242493750.43286
Lets try the log again, this time follow these instructions. 1) shut down squeezecenter 2) navigate to your //log folder and delete the server.log & scanner.log files you find there 3) start up squeezecenter 4) go to Settings > Advanced > Logging > Select Reset Logging Preference 5) manually switch these to = DEBUG (network.cometd) - Cometd protocol loggin (scan.scanner) - Music & Playlist Folder Scanning Check 'save logging settings..' Click "Apply" 6) Recreate the error condition on the SBController 7) shut down squeezecenter 8) navigate to your //log folder, locate the server.log & scanner.log files 9) IN this bug, click on 'add an attachment' 10) locate the server.log file from step 8 and upload it to this bug. DO NOT add it as a comment, we need the whole log file 11) Repeat step 9 & 10 substituting server.log file
Created attachment 5237 [details] as requested No scanner.log file created, only server.log
this may be the smoking gun here-- folder_id 46815 is the folder "Trafassi", and the controller is asking for the contents of the menu, but starting with item *400*. Herman, a couple investigative questions: 1. are there any folders that you've browsed to in Browse Music Folder that have more than 400 items in them? 2. if you browsed to the folder with many items, did you scroll down below the 400 item mark before seeing this blank window issue? if the answer is yes to those two questions, I'm fairly certain where the fix needs to be. [09-05-18 21:47:08.4108] Slim::Web::Cometd::handler (143) Cometd request: [ { channel => "/slim/request", data => { request => [ "00:04:20:16:0c:fa", [ "musicfolder", 400, 200, "menu_all:1", "textkey:T", "menu:musicfolder", "folder_id:46815", ], ], response => "/7fed83b8/slim/request", }, id => 23, }, ]
The root folder already has > 400 entries and since Trafassi is at the T somewhere at the back then I am pretty sure that it already passed the 400 mark so yes on both counts.
I've now reproduced the issue reliably by forcing the chunk count from 200 down to 10. QA doesn't need to spend any more time on this, it's mine to fix now.
(this is for my own debug notes) Browse into a Music Folder with 83 items with BLOCK_SIZE 10. Chunks load in as expected: 20090518 20:42:59.428 WARN player.browse.data - DB.lua:190 ********************************* loading key number 0 20090518 20:42:59.428 WARN player.browse.data - DB.lua:191 ********************************* cFrom: 1 20090518 20:42:59.428 WARN player.browse.data - DB.lua:192 ********************************* cTo: 10 20090518 20:42:59.458 WARN player.browse.data - DB.lua:190 ********************************* loading key number 8 20090518 20:42:59.458 WARN player.browse.data - DB.lua:191 ********************************* cFrom: 81 20090518 20:42:59.458 WARN player.browse.data - DB.lua:192 ********************************* cTo: 83 20090518 20:42:59.503 WARN player.browse.data - DB.lua:190 ********************************* loading key number 1 20090518 20:42:59.503 WARN player.browse.data - DB.lua:191 ********************************* cFrom: 11 20090518 20:42:59.503 WARN player.browse.data - DB.lua:192 ********************************* cTo: 20 20090518 20:42:59.547 WARN player.browse.data - DB.lua:190 ********************************* loading key number 2 20090518 20:42:59.547 WARN player.browse.data - DB.lua:191 ********************************* cFrom: 21 20090518 20:42:59.547 WARN player.browse.data - DB.lua:192 ********************************* cTo: 30 20090518 20:42:59.590 WARN player.browse.data - DB.lua:190 ********************************* loading key number 3 20090518 20:42:59.590 WARN player.browse.data - DB.lua:191 ********************************* cFrom: 31 20090518 20:42:59.590 WARN player.browse.data - DB.lua:192 ********************************* cTo: 40 20090518 20:42:59.635 WARN player.browse.data - DB.lua:190 ********************************* loading key number 4 20090518 20:42:59.635 WARN player.browse.data - DB.lua:191 ********************************* cFrom: 41 20090518 20:42:59.635 WARN player.browse.data - DB.lua:192 ********************************* cTo: 50 20090518 20:42:59.681 WARN player.browse.data - DB.lua:190 ********************************* loading key number 5 20090518 20:42:59.681 WARN player.browse.data - DB.lua:191 ********************************* cFrom: 51 20090518 20:42:59.681 WARN player.browse.data - DB.lua:192 ********************************* cTo: 60 20090518 20:42:59.727 WARN player.browse.data - DB.lua:190 ********************************* loading key number 6 20090518 20:42:59.727 WARN player.browse.data - DB.lua:191 ********************************* cFrom: 61 20090518 20:42:59.727 WARN player.browse.data - DB.lua:192 ********************************* cTo: 70 20090518 20:42:59.770 WARN player.browse.data - DB.lua:190 ********************************* loading key number 7 20090518 20:42:59.770 WARN player.browse.data - DB.lua:191 ********************************* cFrom: 71 20090518 20:42:59.770 WARN player.browse.data - DB.lua:192 ********************************* cTo: 80 Now browse down to item #76, exit the menu, then re-enter. Browse history handler remembers that last index was 76 so it first requests this chunk, which it does (key 7). It then loads the chunk above it (key 6), the chunk above it (key 8), then starts to populate from above key 6 to the top and stalls out. key 5 chunk comes in and then it stops requesting anything more. This results in a blank window. 20090518 20:43:10.529 WARN player.browse - SlimBrowserApplet.lua:209 ----------------- musicfolder menu:musicfolder { --[[table: 0x16ba1900]] index = 76, } 20090518 20:43:10.529 WARN player.browse - SlimBrowserApplet.lua:212 -----------------table: 0x16ba1900 20090518 20:43:10.594 WARN player.browse.data - DB.lua:190 ********************************* loading key number 7 20090518 20:43:10.594 WARN player.browse.data - DB.lua:191 ********************************* cFrom: 71 20090518 20:43:10.594 WARN player.browse.data - DB.lua:192 ********************************* cTo: 80 20090518 20:43:10.639 WARN player.browse.data - DB.lua:190 ********************************* loading key number 6 20090518 20:43:10.639 WARN player.browse.data - DB.lua:191 ********************************* cFrom: 61 20090518 20:43:10.639 WARN player.browse.data - DB.lua:192 ********************************* cTo: 70 20090518 20:43:10.667 WARN player.browse.data - DB.lua:190 ********************************* loading key number 8 20090518 20:43:10.667 WARN player.browse.data - DB.lua:191 ********************************* cFrom: 81 20090518 20:43:10.667 WARN player.browse.data - DB.lua:192 ********************************* cTo: 83 20090518 20:43:10.714 WARN player.browse.data - DB.lua:190 ********************************* loading key number 5 20090518 20:43:10.714 WARN player.browse.data - DB.lua:191 ********************************* cFrom: 51 20090518 20:43:10.714 WARN player.browse.data - DB.lua:192 ********************************* cTo: 60
this is fixed in 7.3 r5772 a brief synopsis of what was happening: controller fetches chunks of data in sets of 200 items at a time when you scroll down to, say, item #410, and then exit back out, there is a "bookmark" of sorts that tells the controller that the next time entering that menu the first chunk it gets should include item #410 and then fill in the missing chunks above and below it until the entire menu has filled in. There was a bug in the code that decided which chunks hadn't been collected yet, which would cause the menu to not load completely, resulting in ugly behavior. QA, to test this fix, browse to menus that have > 200 items and scroll down to places below the 200 item mark, exit the menu, then re-enter the menu. The item that you'd previously scrolled to should be the selected item, and you should be able to scroll all the way to the top and all the way to the bottom of the menu and see items. Try this on at least few different items below the 200 item mark, and if you have a list > 400, go below that mark as well.
Just installed 6038 and the problem is still there. ANy ideas?
(In reply to comment #16) > Just installed 6038 and the problem is still there. ANy ideas? Please try a Factory Reset on your controller. Let me know if that changes the behavior. I just tried it here, with a lib that had 1055 'albums' and was unable to repo the error. I'll try in with a lib of 50k albums next
did the factory reset but that did not change things. I'll try to reinstall r6038. Maybe you fixed a different bug :-)
no change after the reinstall. Literally same behaviour as described initially.
> I'll try in with a lib of 50k albums next Richard - I still believe this is a performance issue. Try browsing a large collection on eg. a ReadyNAS while SC is running on your PC or similar.
Oops... I meant to address James, not Richard, in my previous comment
Did the logs that I provided indicate that this could be timing related? The weird thing is that the bug only appears when scrolling down my music folder and with every folder after a specific boundary (#folders scrolled). No errors or anything. That's why I would be surprised if this were to be timing/NAS related.
not having the old FW to test agains, it does look like the behaviour changed (got worse). First of all the issue arises well before the 400 items mark (around 200) + when I go in a folder, back up, scroll up a bit, go into another, back-out and then back to the original folder then quite a number of folders have content when I first enter but not when I return so the issue seems more persistent than before :-(
Is this related to bug 9004 per chance?
Don't think so as I don;t seem to lose the connection at all. I can brose thru the list with no issues at all and I don;t get any error messages in any logs. It's just that I go into a music folder, it shows content, i go one level up, go to another folder, go back up again and go back to the original folder I went into and the contents are all empty. All the time the controler behaves very responsively. If I could only see all the music in the folders, I would be the happiest SB user on the planet as my entire family (even 9 and 11yo daughters) can use the SB that way.
I am still unable to reproduce this error. I have tried on Ubuntu / Windows / Mac / ReadyNAS, all platforms with controller r6038 perform as expected. I'd like to see cifs/NAS eliminated from the equation changes your experience at all. If there is any disk space on the linux box, I'd like to see if you have the same issue when pointing to a fully local folder. The linux box as described has boatloads of power, but the bottleneck might be in the NAS/cifs structure. That is the only bit I can not setup here to reproduce.
It means I have to buy another disk as the current one does not have enough space available. Let me do that and report back to you. Probably Thursday. Thanks so far.
FWIW, you don't need to copy your entire library over to the Linux server, just one representative problematic directory. Retrieving very long file lists from a directory is a very typically slow task, esp. over networked filesystems. By removing the NAS/cifs component, it will go a long way to proving our current theory, which is a performance bottleneck at that part of the equation. The controller should handle this type of situation better regardless, but some insight on the cause will be most useful, esp. since we now are having trouble reproducing this.
So, new disk arrived, installed and copied all music across (just to make sure the situations are identical). Unfortunately the behaviour is exactly the same and the bug is still there and the network was not the problem.
Any additional logging I can provide to get this resolved?
Adding time worked info I am still unable to replicate this issue. Please retest with 7.4 once SBC firmware is more stable
James, Although slightly disappointing, i'll have a go with 7.4 once stable enough. One question: I noticed that squeezeplay under windows has exactly teh same behaviour which gives me the impression this is server rather than controller related, right? H
To be quite honest with you, I don't know. I have spent lots of time trying to replicate the issue, but have not been able to so far. With the fix's Ben has already put into place on the Controller and a new scanner for 7.4, my hope is that 7.4 fix's the issue for you.
Understood. Anyways, anything I can do to help resolve, just ask (I bought a hard drive already so as long as we stick to those types of expenses I am OK :-) ) When do you recommend I give it a try? Good w-e from NL.
OK...I think we have a build that you can verify on. Please download nightly 7.4 from this location: http://downloads.slimdevices.com/nightly/?ver=7.4 Once you install that version, it should update your controller to r7115 or later I would strongly suggest you factory reset your controller after installing the firmware. Test again and let me know if this error is fixed.
this is an administrative shuffle on priority fields to help make better judgment on the top end of the priority list. P4->P5, P3->P4, and P2->P3.
Herman: Using 7.4 I have not experienced the issue as described. Please try this version and verify that the issue has been addressed for you as well.
Bad news: installed 7.4. As I just bought one of those nifty asrock nettop ION 330 boxes (runs ubuntu client 64BIT as opposed to my existing 32bit server), I installed 7.4 on that box. Since I experienced the exact same issue with squeezeplay I used that to test (7.4 under Ubuntu and squeezeplay 7.4 under windows). So even tho quite some variables have changed (new system, ubuntu client, 64b, 7.4 on client and server), the behaviour is exactly the same and the bug shows itself immediately. Bugger!
I very rarely see the same thing happening on my Controller. Strangely enough, it's mostly my "U2" folder, although I cannot see why this should be. In no way is this a folder with the most albums or the most tracks. (It contains about 20 albums of 15 to 30 songs each). Maybe SC just doesn't like Bono. My "Compilation" folder has the same problem, sometimes. This contains about 150 - 200 albums. Tracks per album ranges from 10 to 50. It also happened once to my "Misc" folder. Basically a dumping ground for several hundred loose tracks. All of the above folders are in my MP3 folder. I haven't noticed the same thing occuring below my FLAC folder, but the amount of FLAC albums and tracks are a lot less. Once or twice browsing up a few levels in the menu and down again made it work, but the other times I had to reset the Controller. One thing I did observe: even though I couldn't see the content of the folder, when I selected the folder and clicked Play I was able to next-next-next through all the albums & songs. This bug isn't a showstopper for me, as the solution is quick and it only happens rarely. But I thought I would mention it here, to indicate it still exists. SC 7.3.4 running on Athlon64 3000+, 1GB ram, 1TB HD, wired. Duet fw's 127 and r6038, wireless.
Could anyone seeing this issue please test 7.4.1 (beta), we have done some changes in that version that may resolve this issue. Let me know if this does fix the issue or not. Marking as fixed for now, till I hear back from someone
No joy. Installed 741 server followed by new controller firmware. Behaviour is exactly the same :-(
do you know whether non-latin characters are being used in the path you're browsing (the full path, not only the last element)?
Created attachment 6098 [details] More info i have attached the directory listing. the bug shows up if i go straight to Trafassi, go out, go up a bit (eg Tina Turner) and then go back to Trafassi again. Then the Trafassi directory is completely empty whereas it had songs before.
Ben - this sounds very similar to what you described: go beyond the chunksize, open a sub folder, go buck up in the first chunk and back etc. I was able to reproduce this that way. Will have to investigate further.
What 7.4.1 controller version are those having problems running? The related fix is in r7839 and higher. I just tested with Music Folder and can't reproduce You can find the version number in settings->advanced->diagnostics.
As per my note above dates 09-10-07, i installed 7.4.1 which caused the remote to update it's FW to 7.4.1 as well. I do not recall what FW version that was. For the sake of completeness, I just re-installed 7.4.1r28848 again (I went back to the 7.4.0 production release). What's weird is that it does not force the 7.4.1. update on the controller (which also downgraded to 7.4.0 with the 7.4.0. server release downgrade). If you can tell me how to force the FW upgrade then happy to try again.
EUREKA!!! emptied the cache still having the old 7.4.0 jive files. dowloaded the latest from testing. restarted the server, controller starts updating and ... guess what: problem gone! I have done some browsing backwards/forwards but I cannot reproduce! HAPPY!!! Will do some more 'field testing' but it looks like this can be closed. Thanks. Herman
Anyone else on the bug having success or failures? Awaiting further customer validation.
Marking as verified based on customer feedback.