Can you attach a file where this happens?

Created attachment 2457 [details]
basically, it applies to ANY mp3, but I am attaching one as example

I noticed, there's a bug 5256 about the same situation as mine...

I have come a little further, if anyone cares: 

Result 1: I have launched softsqueeze (from the same MacBook (Leopard) where SlimServer was running) and connected to the same slimserver: the issue DID reproduce -- mp3 tracks are starting to play from ±12s second.

Result 2: I have installed the same version of slimserver on my PC notebook (win2k) and the issue DID NOT reproduce. 

Result 3: On MacBook (Leopard), the music library is located on mounted NFS volume. So, to see if this is related to network, I have copied the mp3 albums to local HDD. The issue DID NOT reproduce!

At the same time, .flac files are playing with no problem! I will now try to play with file permissions on the mounted NFS volume to see if it has eny effect.

Thanks,

Eugene 

Just to be clear:  Is this on Transporter or SoftSqueeze?  Is see both below in your content.

The issue affects BOTH transporter and softaqueeze and reproducable on both of them too.

Alan, can you take a look at this?

Since it affects both Transporter and SS, it's probably not a firmware bug.

Eugene, if you come up with any more observations about the circumstances under which you get the problem then that would be useful. Also a debug-level log for player.source would he helpful.

I'll try to arrange logs. I also thought of installing a 6th version of slimserver on my mac to see if this bug is reproducable. But first, there's a New Year to celebrate tonight :-)

Sorry for delay. Some more testing results;

Today installed earlier (6.5.4) version of slimserver:

>SlimServer Version: 6.5.4 - 12568 - Mac OS X 10.5.1 (9B18) - EN - utf8
>Server IP address: 192.168.11.2
>Perl Version: 5.8.8 darwin-thread-multi-2level
>MySQL Version: 5.0.22-standard

Result: MP3s are playing from the beginning and issue DID NOT REPRODUCE.

I will try to arrange player.log files too, but I need to figure out how :-)

Eugene, I am pretty confused as to how this could have been happening. There would have to be a horrible file-system bug for the NFS-access from Leopard to be the cause but that is the only clue at the moment. Am I right that you are no longer seeing this?

I'm going to close this for now as unreproducible. Please reopen it again if you manage to reproduce it again.

No, you are not right. I am sorry for not making myself clear. 

Let me try to summarize my findings:

1. First, the issue is about SqueezeCenter 7, running on Mac OS X Leopard, reproducable when reading MP3s from NFS share. The issue is reproducable on both: Transporter and Softsqueeze.

2. Second, for the sake of test, I have DOWNGRADED SqueezeCenter 7 back to SlimServer version 6.5.4 on the same machine (Mac OS X Leopard, NFS share). As a result, SlimServer version 6 DID NOT have this problem -- MP3s were playing fine through SlimServer 6.5.4.

It means that the problem IS WITH SqueezeCenter 7 and IS reproducable.

Other findings:
- it affects only NFS shares. SMB shares and local files are playing fine.
- it does NOT affect .flac files, regardless of their location

Please let me know if you need to receive any technical details or logs.

Eugene

Thanks for the clarification. A pair of logs for the same MP3 file and same version of SC, one with the problem and one without (presumably one via NFS and one local, both on Leopard; or one from Leopard and one from Win2K) might help. Please set logging level player.source=debug (on Settings->Advanced->Logging).

Is there a delay before the audio starts at the 12th second of the track? If so, how long is the delay?

What does the timer on the now-playing counter say after the audio starts: does it start counting up from 0 or from 12?

Thanks.

Will do the log part once I get home later today.

>Is there a delay before the audio starts at the 12th second of the track? If
>so, how long is the delay?

No, there's no silence gap. Audio starts playing right away, but not from the beginning of the track. 

One more note, "12th second" is an approximate value -- I didn't check it with a stopwatch. But for each track it is exacly the same length: when skipping tracks in the playlist back and forth, the tracks start from the same position all the time.

>What does the timer on the now-playing counter say after the audio starts: does
>it start counting up from 0 or from 12?

"Now playing" timer always starts from 0. I also tried to Rewind the song to the beginning and it worked -- I was able to rewind to the very beginning of the track. 

Eugene

Here goes the logging. What I've done:
1. Turned logging on as you recommended 
2. Playing: 
a) MP3 file from NFS share: file:///Network/Servers/nas.local/mnt/hda/music/1flac/Bravo/Zvjozdnyj%20Katalog/03%20Zemfira%20-%20Kak%20Byt%27.mp3
b) The same file from local machine: file:///Users/eugened/Desktop/Bravo/Zvjozdnyj%20Katalog/03%20Zemfira%20-%20Kak%20Byt%27.mp3

Here's the output from log file:

[21:19:21.0926] Slim::Player::Source::playmode (298) 00:04:20:10:05:5d: Switching to mode stop from pause
[21:19:21.1040] Slim::Player::Source::playmode (397) 00:04:20:10:05:5d New play mode: stop
[21:19:21.1043] Slim::Player::Source::playmode (442) 00:04:20:10:05:5d: Stopping and clearing out old chunks
[21:19:21.1078] Slim::Player::Source::resetSong (1590) Resetting song buffer.
[21:19:21.1082] Slim::Player::Source::resetSongQueue (1424) Resetting song queue
[21:19:21.1088] Slim::Player::Source::resetSongQueue (1434) Song queue is now 0
[21:19:21.1093] Slim::Player::Source::playmode (553) 00:04:20:10:05:5d: Current playmode: stop
[21:19:21.1096] Slim::Player::Source::streamingSongIndex (1350) Adding song index 0 to song queue
[21:19:21.1098] Slim::Player::Source::streamingSongIndex (1354) Clearing out song queue first
[21:19:21.1104] Slim::Player::Source::streamingSongIndex (1371) Song queue is now 0
[21:19:21.1117] Slim::Player::Source::playmode (298) 00:04:20:10:05:5d: Switching to mode stop from stop
[21:19:21.1120] Slim::Player::Source::playmode (305) Already in playmode stop : ignoring mode change
[21:19:21.1123] Slim::Player::Source::streamingSongIndex (1350) Adding song index 0 to song queue
[21:19:21.1125] Slim::Player::Source::streamingSongIndex (1354) Clearing out song queue first
[21:19:21.1127] Slim::Player::Source::streamingSongIndex (1371) Song queue is now 0
[21:19:21.1131] Slim::Player::Source::playmode (298) 00:04:20:10:05:5d: Switching to mode play from stop
[21:19:21.1136] Slim::Player::Source::resetSong (1590) Resetting song buffer.
[21:19:21.1146] Slim::Player::Source::openSong (1685) Trying to open: file:///Network/Servers/nas.local/mnt/hda/music/1flac/Bravo/Zvjozdnyj%20Katalog/03%20Zemfira%20-%20Kak%20Byt%27.mp3
[21:19:21.1156] Slim::Player::Source::openSong (1862) duration: [200.882] size: [6305903] endian [] offset: [1166] for file:///Network/Servers/nas.local/mnt/hda/music/1flac/Bravo/Zvjozdnyj%20Katalog/03%20Zemfira%20-%20Kak%20Byt%27.mp3
[21:19:21.1162] Slim::Player::TranscodingHelper::getConvertCommand (203) undermax = 1, type = mp3, transporter = 00:04:20:10:05:5d
[21:19:21.1165] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wma-transporter-00:04:20:10:05:5d
[21:19:21.1167] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wma-*-00:04:20:10:05:5d
[21:19:21.1170] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wma-transporter-*
[21:19:21.1172] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wma-squeezebox2-*
[21:19:21.1174] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wma-*-*
[21:19:21.1176] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-ogg-transporter-00:04:20:10:05:5d
[21:19:21.1195] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-ogg-*-00:04:20:10:05:5d
[21:19:21.1197] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-ogg-transporter-*
[21:19:21.1199] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-ogg-squeezebox2-*
[21:19:21.1425] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-ogg-*-*
[21:19:21.1430] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-flc-transporter-00:04:20:10:05:5d
[21:19:21.1432] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-flc-*-00:04:20:10:05:5d
[21:19:21.1434] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-flc-transporter-*
[21:19:21.1436] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-flc-squeezebox2-*
[21:19:21.1438] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-flc-*-*
[21:19:21.1440] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-aif-transporter-00:04:20:10:05:5d
[21:19:21.1442] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-aif-*-00:04:20:10:05:5d
[21:19:21.1444] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-aif-transporter-*
[21:19:21.1447] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-aif-squeezebox2-*
[21:19:21.1449] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-aif-*-*
[21:19:21.1451] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wav-transporter-00:04:20:10:05:5d
[21:19:21.1453] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wav-*-00:04:20:10:05:5d
[21:19:21.1455] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wav-transporter-*
[21:19:21.1457] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wav-squeezebox2-*
[21:19:21.1459] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wav-*-*
[21:19:21.1462] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-mp3-transporter-00:04:20:10:05:5d
[21:19:21.1464] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-mp3-*-00:04:20:10:05:5d
[21:19:21.1466] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-mp3-transporter-*
[21:19:21.1468] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-mp3-squeezebox2-*
[21:19:21.1470] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-mp3-*-*
[21:19:21.1472] Slim::Player::TranscodingHelper::enabledFormat (105) Checking to see if mp3-mp3-*-* is enabled
[21:19:21.1474] Slim::Player::TranscodingHelper::checkBin (146)    enabled
[21:19:21.1476] Slim::Player::TranscodingHelper::checkBin (148)   Found command: -
[21:19:21.1485] Slim::Player::TranscodingHelper::getConvertCommand (308) Matched Format: mp3 Type: mp3 Command: -
[21:19:21.1487] Slim::Player::Source::openSong (1889) This is an mp3 file: file:///Network/Servers/nas.local/mnt/hda/music/1flac/Bravo/Zvjozdnyj%20Katalog/03%20Zemfira%20-%20Kak%20Byt%27.mp3
[21:19:21.1489] Slim::Player::Source::openSong (1890)   file type: mp3 format: mp3 inrate: 251 maxRate: 0
[21:19:21.1491] Slim::Player::Source::openSong (1891)   command: -
[21:19:21.1495] Slim::Player::Source::openSong (1914) Opening file /Network/Servers/nas.local/mnt/hda/music/1flac/Bravo/Zvjozdnyj Katalog/03 Zemfira - Kak Byt'.mp3
[21:19:21.1540] Slim::Player::Source::openSong (1918) Seeking in 1166 into /Network/Servers/nas.local/mnt/hda/music/1flac/Bravo/Zvjozdnyj Katalog/03 Zemfira - Kak Byt'.mp3
[21:19:21.1598] Slim::Player::Source::openSong (1945) MP3 file was encoded with LAME3.96 
[21:19:21.1600] Slim::Player::Source::openSong (1947) MP3 contains encoder delay information (576/1728), will be played gapless
[21:19:21.1604] Slim::Player::Source::openSong (2053) Streaming with format: mp3
[21:19:21.1634] Slim::Player::Source::playmode (397) 00:04:20:10:05:5d New play mode: play
[21:19:21.1651] Slim::Player::Transporter::play (99) Setting DigitalInput to 0 for [file:///Network/Servers/nas.local/mnt/hda/music/1flac/Bravo/Zvjozdnyj%20Katalog/03%20Zemfira%20-%20Kak%20Byt%27.mp3]
[21:19:21.1657] Slim::Player::Transporter::setDigitalInput (179) Switching to digital input 0
[21:19:21.1671] Slim::Player::Source::playmode (553) 00:04:20:10:05:5d: Current playmode: play
[21:19:21.2562] Slim::Player::Source::readNextChunk (2163) Sending 0 bytes of silence.
[21:19:21.3880] Slim::Player::Source::trackStartEvent (1461) Got a track starting event
[21:19:21.3884] Slim::Player::Source::trackStartEvent (1477) Song 0 has now started playing
[21:19:21.3895] Slim::Player::Source::trackStartEvent (1500) Song queue is now 0
[21:20:16.3341] Slim::Player::Source::readNextChunk (2312) Read to end of file or pipe
[21:20:16.3583] Slim::Player::Source::readNextChunk (2335) end of file or error on socket, opening next song, (song pos: 5258829(tell says: . 6307405), totalbytes: 6305903)
[21:20:16.3588] Slim::Player::Source::gotoNext (1206) Opening next song...
[21:20:16.3597] Slim::Player::Source::playmode (298) 00:04:20:10:05:5d: Switching to mode playout-stop from play
[21:20:16.3602] Slim::Player::Source::playmode (397) 00:04:20:10:05:5d New play mode: playout-stop
[21:20:16.3619] Slim::Player::Source::playmode (553) 00:04:20:10:05:5d: Current playmode: playout-stop
[21:20:16.3622] Slim::Player::Source::dropStreamingConnection (1315) No pending chunks - we're dropping the streaming connection
[21:20:16.3661] Slim::Player::Source::readNextChunk (2393) 00:04:20:10:05:5d: Can't opennext, returning no chunk.
[21:21:57.8218] Slim::Player::Source::decoderUnderrun (579) 00:04:20:10:05:5d: Decoder underrun while this mode: playout-stop
[21:21:57.8223] Slim::Player::Source::nextsong (1551) The next song is number 0, was 0
[21:21:57.8230] Slim::Player::Source::nextsong (1551) The next song is number 0, was 0
[21:22:07.8196] Slim::Player::Source::underrun (676) 00:04:20:10:05:5d: Underrun while this mode: playout-stop
[21:22:07.8207] Slim::Player::Source::playmode (298) 00:04:20:10:05:5d: Switching to mode stop from playout-stop
[21:22:07.8212] Slim::Player::Source::playmode (397) 00:04:20:10:05:5d New play mode: stop
[21:22:07.8216] Slim::Player::Source::playmode (442) 00:04:20:10:05:5d: Stopping and clearing out old chunks
[21:22:07.8232] Slim::Player::Source::resetSong (1590) Resetting song buffer.
[21:22:07.8236] Slim::Player::Source::resetSongQueue (1424) Resetting song queue
[21:22:07.8239] Slim::Player::Source::resetSongQueue (1434) Song queue is now 0
[21:22:07.8245] Slim::Player::Source::playmode (553) 00:04:20:10:05:5d: Current playmode: stop
[21:22:07.8249] Slim::Player::Source::streamingSongIndex (1350) Adding song index 0 to song queue
[21:22:07.8251] Slim::Player::Source::streamingSongIndex (1354) Clearing out song queue first
[21:22:07.8255] Slim::Player::Source::streamingSongIndex (1371) Song queue is now 0
[21:22:13.6076] Slim::Player::Source::streamingSongIndex (1350) Adding song index 0 to song queue
[21:22:13.6079] Slim::Player::Source::streamingSongIndex (1354) Clearing out song queue first
[21:22:13.6082] Slim::Player::Source::streamingSongIndex (1371) Song queue is now 0
[21:22:13.6088] Slim::Player::Source::playmode (298) 00:04:20:10:05:5d: Switching to mode stop from stop
[21:22:13.6090] Slim::Player::Source::playmode (305) Already in playmode stop : ignoring mode change
[21:22:39.0835] Slim::Player::Source::playmode (298) 00:04:20:10:05:5d: Switching to mode stop from stop
[21:22:39.0837] Slim::Player::Source::playmode (305) Already in playmode stop : ignoring mode change
[21:22:39.0841] Slim::Player::Source::streamingSongIndex (1350) Adding song index 0 to song queue
[21:22:39.0843] Slim::Player::Source::streamingSongIndex (1354) Clearing out song queue first
[21:22:39.0845] Slim::Player::Source::streamingSongIndex (1371) Song queue is now 0
[21:22:39.0855] Slim::Player::Source::playmode (298) 00:04:20:10:05:5d: Switching to mode stop from stop
[21:22:39.0858] Slim::Player::Source::playmode (305) Already in playmode stop : ignoring mode change
[21:22:39.0860] Slim::Player::Source::streamingSongIndex (1350) Adding song index 0 to song queue
[21:22:39.0862] Slim::Player::Source::streamingSongIndex (1354) Clearing out song queue first
[21:22:39.0864] Slim::Player::Source::streamingSongIndex (1371) Song queue is now 0
[21:22:39.0868] Slim::Player::Source::playmode (298) 00:04:20:10:05:5d: Switching to mode play from stop
[21:22:39.0872] Slim::Player::Source::resetSong (1590) Resetting song buffer.
[21:22:39.0883] Slim::Player::Source::openSong (1685) Trying to open: file:///Users/eugened/Desktop/Bravo/Zvjozdnyj%20Katalog/03%20Zemfira%20-%20Kak%20Byt%27.mp3
[21:22:39.0892] Slim::Player::Source::openSong (1862) duration: [200.882] size: [6305903] endian [] offset: [1166] for file:///Users/eugened/Desktop/Bravo/Zvjozdnyj%20Katalog/03%20Zemfira%20-%20Kak%20Byt%27.mp3
[21:22:39.0900] Slim::Player::TranscodingHelper::getConvertCommand (203) undermax = 1, type = mp3, transporter = 00:04:20:10:05:5d
[21:22:39.0903] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wma-transporter-00:04:20:10:05:5d
[21:22:39.0905] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wma-*-00:04:20:10:05:5d
[21:22:39.0907] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wma-transporter-*
[21:22:39.0910] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wma-squeezebox2-*
[21:22:39.0912] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wma-*-*
[21:22:39.0914] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-ogg-transporter-00:04:20:10:05:5d
[21:22:39.0916] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-ogg-*-00:04:20:10:05:5d
[21:22:39.0918] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-ogg-transporter-*
[21:22:39.0921] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-ogg-squeezebox2-*
[21:22:39.0923] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-ogg-*-*
[21:22:39.0926] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-flc-transporter-00:04:20:10:05:5d
[21:22:39.0928] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-flc-*-00:04:20:10:05:5d
[21:22:39.0930] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-flc-transporter-*
[21:22:39.0933] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-flc-squeezebox2-*
[21:22:39.0935] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-flc-*-*
[21:22:39.0937] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-aif-transporter-00:04:20:10:05:5d
[21:22:39.0939] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-aif-*-00:04:20:10:05:5d
[21:22:39.0941] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-aif-transporter-*
[21:22:39.0943] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-aif-squeezebox2-*
[21:22:39.0946] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-aif-*-*
[21:22:39.0948] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wav-transporter-00:04:20:10:05:5d
[21:22:39.0950] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wav-*-00:04:20:10:05:5d
[21:22:39.0952] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wav-transporter-*
[21:22:39.0954] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wav-squeezebox2-*
[21:22:39.0958] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-wav-*-*
[21:22:39.0960] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-mp3-transporter-00:04:20:10:05:5d
[21:22:39.0962] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-mp3-*-00:04:20:10:05:5d
[21:22:39.0964] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-mp3-transporter-*
[21:22:39.0966] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-mp3-squeezebox2-*
[21:22:39.0968] Slim::Player::TranscodingHelper::checkBin (138) Checking formats for: mp3-mp3-*-*
[21:22:39.0971] Slim::Player::TranscodingHelper::enabledFormat (105) Checking to see if mp3-mp3-*-* is enabled
[21:22:39.0973] Slim::Player::TranscodingHelper::checkBin (146)    enabled
[21:22:39.0975] Slim::Player::TranscodingHelper::checkBin (148)   Found command: -
[21:22:39.0988] Slim::Player::TranscodingHelper::getConvertCommand (308) Matched Format: mp3 Type: mp3 Command: -
[21:22:39.0991] Slim::Player::Source::openSong (1889) This is an mp3 file: file:///Users/eugened/Desktop/Bravo/Zvjozdnyj%20Katalog/03%20Zemfira%20-%20Kak%20Byt%27.mp3
[21:22:39.0993] Slim::Player::Source::openSong (1890)   file type: mp3 format: mp3 inrate: 251 maxRate: 0
[21:22:39.0995] Slim::Player::Source::openSong (1891)   command: -
[21:22:39.1000] Slim::Player::Source::openSong (1914) Opening file /Users/eugened/Desktop/Bravo/Zvjozdnyj Katalog/03 Zemfira - Kak Byt'.mp3
[21:22:39.1003] Slim::Player::Source::openSong (1918) Seeking in 1166 into /Users/eugened/Desktop/Bravo/Zvjozdnyj Katalog/03 Zemfira - Kak Byt'.mp3
[21:22:39.1155] Slim::Player::Source::openSong (1945) MP3 file was encoded with LAME3.96 
[21:22:39.1158] Slim::Player::Source::openSong (1947) MP3 contains encoder delay information (576/1728), will be played gapless
[21:22:39.1161] Slim::Player::Source::openSong (2053) Streaming with format: mp3
[21:22:39.1204] Slim::Player::Source::playmode (397) 00:04:20:10:05:5d New play mode: play
[21:22:39.1224] Slim::Player::Transporter::play (99) Setting DigitalInput to 0 for [file:///Users/eugened/Desktop/Bravo/Zvjozdnyj%20Katalog/03%20Zemfira%20-%20Kak%20Byt%27.mp3]
[21:22:39.1227] Slim::Player::Transporter::setDigitalInput (179) Switching to digital input 0
[21:22:39.1239] Slim::Player::Source::playmode (553) 00:04:20:10:05:5d: Current playmode: play
[21:22:39.2143] Slim::Player::Source::readNextChunk (2163) Sending 0 bytes of silence.
[21:22:39.3563] Slim::Player::Source::trackStartEvent (1461) Got a track starting event
[21:22:39.3567] Slim::Player::Source::trackStartEvent (1477) Song 0 has now started playing
[21:22:39.3579] Slim::Player::Source::trackStartEvent (1500) Song queue is now 0
[21:24:08.1563] Slim::Player::Source::readNextChunk (2268) Reduced chunksize to 14447 at end of file (6305903 - 6291456)
[21:24:08.5727] Slim::Player::Source::readNextChunk (2268) Reduced chunksize to 2594 at end of file (6305903 - 6303309)
[21:24:08.5731] Slim::Player::Source::readNextChunk (2312) Read to end of file or pipe
[21:24:08.5736] Slim::Player::Source::readNextChunk (2335) end of file or error on socket, opening next song, (song pos: 6303309(tell says: . 6307405), totalbytes: 6305903)
[21:24:08.5740] Slim::Player::Source::gotoNext (1206) Opening next song...
[21:24:08.5744] Slim::Player::Source::playmode (298) 00:04:20:10:05:5d: Switching to mode playout-stop from play
[21:24:08.5749] Slim::Player::Source::playmode (397) 00:04:20:10:05:5d New play mode: playout-stop
[21:24:08.5765] Slim::Player::Source::playmode (553) 00:04:20:10:05:5d: Current playmode: playout-stop
[21:24:08.5768] Slim::Player::Source::dropStreamingConnection (1315) No pending chunks - we're dropping the streaming connection
[21:24:08.5808] Slim::Player::Source::readNextChunk (2393) 00:04:20:10:05:5d: Can't opennext, returning no chunk.
[21:25:50.0473] Slim::Player::Source::decoderUnderrun (579) 00:04:20:10:05:5d: Decoder underrun while this mode: playout-stop
[21:25:50.0478] Slim::Player::Source::nextsong (1551) The next song is number 0, was 0
[21:25:50.0484] Slim::Player::Source::nextsong (1551) The next song is number 0, was 0
[21:26:00.0268] Slim::Player::Source::underrun (676) 00:04:20:10:05:5d: Underrun while this mode: playout-stop
[21:26:00.0274] Slim::Player::Source::playmode (298) 00:04:20:10:05:5d: Switching to mode stop from playout-stop
[21:26:00.0279] Slim::Player::Source::playmode (397) 00:04:20:10:05:5d New play mode: stop
[21:26:00.0282] Slim::Player::Source::playmode (442) 00:04:20:10:05:5d: Stopping and clearing out old chunks
[21:26:00.0295] Slim::Player::Source::resetSong (1590) Resetting song buffer.
[21:26:00.0298] Slim::Player::Source::resetSongQueue (1424) Resetting song queue
[21:26:00.0301] Slim::Player::Source::resetSongQueue (1434) Song queue is now 0
[21:26:00.0309] Slim::Player::Source::playmode (553) 00:04:20:10:05:5d: Current playmode: stop
[21:26:00.0312] Slim::Player::Source::streamingSongIndex (1350) Adding song index 0 to song queue
[21:26:00.0315] Slim::Player::Source::streamingSongIndex (1354) Clearing out song queue first
[21:26:00.0318] Slim::Player::Source::streamingSongIndex (1371) Song queue is now 0
 

Interesting, the offset value is correct for the start of the file but at the end of the file the song pos value is much different.

Two more comments: 
I am looking at the progress bar (now playing) on transporter: when song ends, it shows 15-20% till the end of the song.
I have also time-lapsed the amount of time it skips from the beginning of the track: it's actually more than 12 seconds -- it's around 22 seconds.

Feel free to let me know if I can be of any further help -- I'll stay awake for an hour or so -- it's almost 10pm here.

Steven could you have a look at this priority bug?

This is really weird. It is like the first megabyte (the missing data is almost exactly 1MB) gets skipped without any error being raised. It is as if the seek to position 1166 (the initial offset) gets misinterpreted. It is possible that change 10247 is implicated: I am investigating.

The file bitrate is reported as 251kb/s, so presumably this is VBR. 1MB at 251kb/s would equate to 33s, but since 251 is only an average across the whole file, the variation caused by VBR could account for the difference between 33s and the observed 22s.

The MP3 file which was played and logged is attached to this thread.

I think that I may have found the problem. What I do not understand is why it worked when you reverted to SlimServer 6.5.4. If I have found the cause then it was introduced with 6.5.1. I can see how it could be platform-specific although it really surprises me that local vs. NFS makes a difference. I also guess that it could be sensitive to the specific track being played. Do you recall if you tried the same track (03 Zemfira - Kak Byt'.mp3) when testing with 6.5.4? 

Anyway, I'll add the fix (the code is certainly wrong) and it should be in tonight's build.

Alan, were you able to reproduce before the fix?

No, I could not reproduce. It would be good if you could reproduce it. I do not have a suitable test environment. You need SC on Leopard and the files on an NFS-mounted drive. 

Change 16072 committed.

(In reply to comment #22)
> I think that I may have found the problem. What I do not understand is why it
> worked when you reverted to SlimServer 6.5.4. If I have found the cause then it
> was introduced with 6.5.1. I can see how it could be platform-specific although
> it really surprises me that local vs. NFS makes a difference. I also guess that
> it could be sensitive to the specific track being played. Do you recall if you
> tried the same track (03 Zemfira - Kak Byt'.mp3) when testing with 6.5.4? 
> 
> Anyway, I'll add the fix (the code is certainly wrong) and it should be in
> tonight's build.
> 

To be honest, I don't remember if I tried this particular track on 6.5.4 or not. But I am 100% sure that other tracks in the same album were playing fine on 6.5.4 and were not playing fine on 7.

I have setup a NFS share on a ReadyNAS and can now reproduce the issue.  Looking forward to testing against change 16072 tomorrow.

Just downloaded and installed today's build -- issue is not reproduced anymore, so I assume it is fixed. 
Thank you!

Thank you for all your testing.

Fix works on my end as well.  Thanks Alan!

This bug has recently been fixed in the latest release of SqueezeCenter 7.0.1

Please try that version, if you still see the error, then reopen this bug.

To download this version, please navigate to: http://www.slimdevices.com/su_downloads.html