Still WAV/FLAC-Problem on 1671

[belu]

After (exactly) 10 seconds playback of a WAV or flac-file stops for about 15 seconds. then goes on with random rebuffering (after about 1 or 2 or even more minutes). 320kbps m4a plays flawlessly (but see the log at 18:06:50!). Only 128 kbps mp3 seems to be ok (even accordig to the log)

Here is the
Log file: firefly.log

2007-09-26 16:22:12 (d2303ab9): Firefly Version svn-1671: Starting with debuglevel 2
2007-09-26 16:22:13 (d2303ab9): Plugin loaded: w32-event/svn-1671
2007-09-26 16:22:13 (d2303ab9): Plugin loaded: ssc-wma/svn-1671
2007-09-26 16:22:13 (d2303ab9): Plugin loaded: ssc-ffmpeg/svn-1671
2007-09-26 16:22:13 (d2303ab9): Plugin loaded: rsp/svn-1671
2007-09-26 16:22:13 (d2303ab9): Plugin loaded: daap/svn-1671
2007-09-26 16:22:13 (d2303ab9): Starting rendezvous daemon
2007-09-26 16:22:13 (d2303ab9): Building drive mapping table from C:ProgrammeFirefly Media Servermapping.ini
2007-09-26 16:22:13 (d2303ab9): Initializing database
2007-09-26 16:22:14 (d2303ab9): Starting web server from C:ProgrammeFirefly Media Serveradmin-root on port 9999
2007-09-26 16:22:14 (d2303ab9): Registering rendezvous names
2007-09-26 16:22:14 (d2303ab9): Serving 3631 songs. Startup complete in 2 seconds
2007-09-26 16:22:14 (d2303ab9): Rescanning database
2007-09-26 16:22:29 (d2303ab9): Starting playlist scan
2007-09-26 16:22:30 (d2303ab9): Updating playlists
2007-09-26 16:22:30 (d2303ab9): Scanned 3631 songs (was 3631) in 16 seconds
2007-09-26 16:23:51 (e3c1adb7): Session 0: Streaming file ‘Duo-Sonaten 0001.flac’ to 192.168.2.100 (offset 0)
2007-09-26 16:24:16 (b7e8f1c6): Session 0: Streaming file ‘Duo-Sonaten 0001.flac’ to 192.168.2.100 (offset 0)
2007-09-26 16:24:18 (e3c1adb7): Error writing to client socket: Eine bestehende Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen.
2007-09-26 16:24:34 (e3c352da): Session 0: Streaming file ‘Duo-Sonaten 0002.flac’ to 192.168.2.100 (offset 0)
2007-09-26 16:24:35 (b7e8f1c6): Error writing to client socket: Eine bestehende Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen.
2007-09-26 16:25:43 (b7ea96e9): Session 0: Streaming file ‘Duo-Sonaten 0003.flac’ to 192.168.2.100 (offset 0)
2007-09-26 16:25:45 (e3c352da): Error writing to client socket: Eine bestehende Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen.
2007-09-26 16:26:53 (e3c4f7fd): Session 0: Streaming file ‘Duo-Sonaten 0004.flac’ to 192.168.2.100 (offset 0)
2007-09-26 16:26:54 (b7ea96e9): Error writing to client socket: Eine bestehende Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen.
…
2007-09-26 18:05:55 (b7f3e95a): Session 0: Streaming file ’01 – Send a prayer.mp3′ to 192.168.2.100 (offset 0)
2007-09-26 18:06:49 (e3cd31ac): Session 0: Streaming file ’01-Stay On _C_.m4a’ to 192.168.2.100 (offset 0)
2007-09-26 18:06:50 (b7f3e95a): Write error: Eine bestehende Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen.
2007-09-26 18:09:11 (e3cdbe0d): Session 0: Streaming file ’02-Where Is the Line.m4a’ to 192.168.2.100 (offset 0)

BeLu

my 5-cent-english-translation of the german phrase:
“Connection was interrupted by the host-computer’s sofware”

[rpedde]

@belu wrote:

After (exactly) 10 seconds playback of a WAV or flac-file stops for about 15 seconds. then goes on with random rebuffering (after about 1 or 2 or even more minutes). 320kbps m4a plays flawlessly (but see the log at 18:06:50!). Only 128 kbps mp3 seems to be ok (even accordig to the log)

Here is the
Log file: firefly.log

2007-09-26 16:22:12 (d2303ab9): Firefly Version svn-1671: Starting with debuglevel 2
2007-09-26 16:22:13 (d2303ab9): Plugin loaded: w32-event/svn-1671
2007-09-26 16:22:13 (d2303ab9): Plugin loaded: ssc-wma/svn-1671
2007-09-26 16:22:13 (d2303ab9): Plugin loaded: ssc-ffmpeg/svn-1671
2007-09-26 16:22:13 (d2303ab9): Plugin loaded: rsp/svn-1671
2007-09-26 16:22:13 (d2303ab9): Plugin loaded: daap/svn-1671
2007-09-26 16:22:13 (d2303ab9): Starting rendezvous daemon
2007-09-26 16:22:13 (d2303ab9): Building drive mapping table from C:ProgrammeFirefly Media Servermapping.ini
2007-09-26 16:22:13 (d2303ab9): Initializing database
2007-09-26 16:22:14 (d2303ab9): Starting web server from C:ProgrammeFirefly Media Serveradmin-root on port 9999
2007-09-26 16:22:14 (d2303ab9): Registering rendezvous names
2007-09-26 16:22:14 (d2303ab9): Serving 3631 songs. Startup complete in 2 seconds
2007-09-26 16:22:14 (d2303ab9): Rescanning database
2007-09-26 16:22:29 (d2303ab9): Starting playlist scan
2007-09-26 16:22:30 (d2303ab9): Updating playlists
2007-09-26 16:22:30 (d2303ab9): Scanned 3631 songs (was 3631) in 16 seconds
2007-09-26 16:23:51 (e3c1adb7): Session 0: Streaming file ‘Duo-Sonaten 0001.flac’ to 192.168.2.100 (offset 0)
2007-09-26 16:24:16 (b7e8f1c6): Session 0: Streaming file ‘Duo-Sonaten 0001.flac’ to 192.168.2.100 (offset 0)
2007-09-26 16:24:18 (e3c1adb7): Error writing to client socket: Eine bestehende Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen.
2007-09-26 16:24:34 (e3c352da): Session 0: Streaming file ‘Duo-Sonaten 0002.flac’ to 192.168.2.100 (offset 0)
2007-09-26 16:24:35 (b7e8f1c6): Error writing to client socket: Eine bestehende Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen.
2007-09-26 16:25:43 (b7ea96e9): Session 0: Streaming file ‘Duo-Sonaten 0003.flac’ to 192.168.2.100 (offset 0)
2007-09-26 16:25:45 (e3c352da): Error writing to client socket: Eine bestehende Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen.
2007-09-26 16:26:53 (e3c4f7fd): Session 0: Streaming file ‘Duo-Sonaten 0004.flac’ to 192.168.2.100 (offset 0)
2007-09-26 16:26:54 (b7ea96e9): Error writing to client socket: Eine bestehende Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen.
…
2007-09-26 18:05:55 (b7f3e95a): Session 0: Streaming file ’01 – Send a prayer.mp3′ to 192.168.2.100 (offset 0)
2007-09-26 18:06:49 (e3cd31ac): Session 0: Streaming file ’01-Stay On _C_.m4a’ to 192.168.2.100 (offset 0)
2007-09-26 18:06:50 (b7f3e95a): Write error: Eine bestehende Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen.
2007-09-26 18:09:11 (e3cdbe0d): Session 0: Streaming file ’02-Where Is the Line.m4a’ to 192.168.2.100 (offset 0)

BeLu

my 5-cent-english-translation of the german phrase:
“Connection was interrupted by the host-computer’s sofware”

How are you connected? Wired, or wireless?

That really honestly looks like bad connection.

[belu]

Wireless connection, indeed
but I don’t have any problems like this with 1568 (nor did I have any with earlier versions).

BeLu

[S80_UK]

Hi Ron, All,

I am seeing the same issues as Belu – I am testing under Win XP and see this with builds 1671 and 1673. Went back to 1586, and even back to 1359. The problem is not there with the old versions. Back to latest and the problem comes back. Very definitely not a simple wireless issue. I am trying to capture something meaningful in the logs with debug at level 9, but no luck yet.

From where Firefly opens the file with

2007-10-06 23:30:48 (2d39ad9e): Executing: select * from songs where id=469
2007-10-06 23:30:48 (2d39ad9e): Entering config_set_status
2007-10-06 23:30:48 (2d39ad9e): Exiting config_set_status
2007-10-06 23:30:48 (2d39ad9e): Session 0: Streaming file ’01 – Would You Be Happier .flac’ to 192.168.1.34 (offset 0)
2007-10-06 23:30:48 (2d39ad9e): Transcoding K:freds musicThe CorrsThe Best Of The Corrs1 – Would You Be Happier .flac with ssc-ffmpeg/svn-1673
2007-10-06 23:30:48 (2d39ad9e): opening K:freds musicThe CorrsThe Best Of The Corrs1 – Would You Be Happier .flac
2007-10-06 23:30:48 (2d39ad9e): opening file raw
2007-10-06 23:30:48 (2d39ad9e): Updating Content-Type from text/html to audio/wav
2007-10-06 23:30:48 (2d39ad9e): Updating Connection from close to Close
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): Emitting reponse header Content-Language: en_us
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): Emitting reponse header Content-Type: audio/wav
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): Emitting reponse header Server: Firefly Media Server/svn-1673
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): Emitting reponse header Connection: Close
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): Emitting reponse header Date: Sat, 6 Oct 2007 22:30:48 GMT
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): Channels…….: 2
2007-10-06 23:30:48 (2d39ad9e): Sample rate….: 44100
2007-10-06 23:30:48 (2d39ad9e): Bits/Sample….: 16
2007-10-06 23:30:48 (2d39ad9e): Swab………..: 0
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428

I get nothing except the “writing to socket xxx” even through the rebuffering until I stop the playback and shut down the server. During this time there was one rebuffering session which took maybe 10 seconds to recover. Playback then resumed.

2007-10-06 23:31:20 (2d39ad9e): writing to socket 428
2007-10-06 23:31:20 (2d39ad9e): writing to socket 428
2007-10-06 23:31:20 (2d39ad9e): writing to socket 428
2007-10-06 23:31:20 (2d39ad9e): writing to socket 428
2007-10-06 23:31:23 (2d39ad9e): Error writing to client socket: An established connection was aborted by the software in your host machine.
2007-10-06 23:31:23 (2d39ad9e): Entering config_set_status
2007-10-06 23:31:23 (2d39ad9e): Exiting config_set_status
2007-10-06 23:31:23 (2d39ad9e): Thread 4: Terminating
2007-10-06 23:31:23 (2d39ad9e): Thread 4: Freeing request headers
2007-10-06 23:31:23 (2d39ad9e): Thread 4: Freeing response headers
2007-10-06 23:31:23 (2d39ad9e): Thread 4: Freeing request vars
2007-10-06 23:31:23 (2d39ad9e): Thread 4: Closing fd
2007-10-06 23:31:23 (2d39ad9e): With thread 4 exiting, 0 are still running
2007-10-06 23:31:26 (2d3a39ff): Service about to terminate with error 0
2007-10-06 23:31:27 (49f59e99): Stopping gracefully
2007-10-06 23:31:27 (49f59e99): Stopping rendezvous daemon
2007-10-06 23:31:27 (49f59e99): Closing database
2007-10-06 23:31:27 (49f59e99): Done!
2007-10-06 23:31:27 (49f59e99): Service about to terminate with error 0

PC processor is AMD Athlon 64 at 3G equiv, 2GB RAM. CPU loading stays around 2% or so when Firefly / Soundbridge has these troubles.

Anything else I should try or look for…?

Thanks,

Les.

[rpedde]

@S80_UK wrote:

Hi Ron, All,

I am seeing the same issues as Belu – I am testing under Win XP and see this with builds 1671 and 1673. Went back to 1586, and even back to 1359. The problem is not there with the old versions. Back to latest and the problem comes back. Very definitely not a simple wireless issue. I am trying to capture something meaningful in the logs with debug at level 9, but no luck yet.

From where Firefly opens the file with

2007-10-06 23:30:48 (2d39ad9e): Executing: select * from songs where id=469
2007-10-06 23:30:48 (2d39ad9e): Entering config_set_status
2007-10-06 23:30:48 (2d39ad9e): Exiting config_set_status
2007-10-06 23:30:48 (2d39ad9e): Session 0: Streaming file ’01 – Would You Be Happier .flac’ to 192.168.1.34 (offset 0)
2007-10-06 23:30:48 (2d39ad9e): Transcoding K:freds musicThe CorrsThe Best Of The Corrs1 – Would You Be Happier .flac with ssc-ffmpeg/svn-1673
2007-10-06 23:30:48 (2d39ad9e): opening K:freds musicThe CorrsThe Best Of The Corrs1 – Would You Be Happier .flac
2007-10-06 23:30:48 (2d39ad9e): opening file raw
2007-10-06 23:30:48 (2d39ad9e): Updating Content-Type from text/html to audio/wav
2007-10-06 23:30:48 (2d39ad9e): Updating Connection from close to Close
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): Emitting reponse header Content-Language: en_us
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): Emitting reponse header Content-Type: audio/wav
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): Emitting reponse header Server: Firefly Media Server/svn-1673
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): Emitting reponse header Connection: Close
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): Emitting reponse header Date: Sat, 6 Oct 2007 22:30:48 GMT
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): Channels…….: 2
2007-10-06 23:30:48 (2d39ad9e): Sample rate….: 44100
2007-10-06 23:30:48 (2d39ad9e): Bits/Sample….: 16
2007-10-06 23:30:48 (2d39ad9e): Swab………..: 0
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428
2007-10-06 23:30:48 (2d39ad9e): writing to socket 428

I get nothing except the “writing to socket xxx” even through the rebuffering until I stop the playback and shut down the server. During this time there was one rebuffering session which took maybe 10 seconds to recover. Playback then resumed.

2007-10-06 23:31:20 (2d39ad9e): writing to socket 428
2007-10-06 23:31:20 (2d39ad9e): writing to socket 428
2007-10-06 23:31:20 (2d39ad9e): writing to socket 428
2007-10-06 23:31:20 (2d39ad9e): writing to socket 428
2007-10-06 23:31:23 (2d39ad9e): Error writing to client socket: An established connection was aborted by the software in your host machine.
2007-10-06 23:31:23 (2d39ad9e): Entering config_set_status
2007-10-06 23:31:23 (2d39ad9e): Exiting config_set_status
2007-10-06 23:31:23 (2d39ad9e): Thread 4: Terminating
2007-10-06 23:31:23 (2d39ad9e): Thread 4: Freeing request headers
2007-10-06 23:31:23 (2d39ad9e): Thread 4: Freeing response headers
2007-10-06 23:31:23 (2d39ad9e): Thread 4: Freeing request vars
2007-10-06 23:31:23 (2d39ad9e): Thread 4: Closing fd
2007-10-06 23:31:23 (2d39ad9e): With thread 4 exiting, 0 are still running
2007-10-06 23:31:26 (2d3a39ff): Service about to terminate with error 0
2007-10-06 23:31:27 (49f59e99): Stopping gracefully
2007-10-06 23:31:27 (49f59e99): Stopping rendezvous daemon
2007-10-06 23:31:27 (49f59e99): Closing database
2007-10-06 23:31:27 (49f59e99): Done!
2007-10-06 23:31:27 (49f59e99): Service about to terminate with error 0

PC processor is AMD Athlon 64 at 3G equiv, 2GB RAM. CPU loading stays around 2% or so when Firefly / Soundbridge has these troubles.

Anything else I should try or look for…?

Thanks,

Les.

I didn’t have problems with wav streaming after 1673. :/

I’ll try again to repro this.

— Ron

[mpoly]

Here’s my 5 cents (euro) worth of observations:

Setup:
* Windows XP
* No problem with 1586
* 1673 has the same problem that belu reports
* Soundbridge reports 99% WiFi signal, and WMP streams WAVs OK, so the connection is not suspect.
* There is a machine B with a 100mbps wired connection, connection tested using FTP transfers, line speed known to be good.

Observations:
* FF streaming a file locally (wget http://localhost:9999/rsp/stream/7254) runs at 3.6 M/Sec, no pauses.
* FF streaming to machine B gets me 160K/s, not enough to serve uncompressed audio.
* FF streaming to machine B via an SSH tunnel to machine A gets me a respectable 1.8 M/Sec

It appears to me that, for some reason, FF streams very slowly to the network interface, at least compared to the speed when streaming to the local interface.

After rolling back to 1586, I get 5M/s+ on both the local and the remote interface.

Can anyone recreate the above test? Any other testing/information that I may provide?

Thanks,

Michael

[rpedde]

@mpoly wrote:

Here’s my 5 cents (euro) worth of observations:

Setup:
* Windows XP
* No problem with 1586
* 1673 has the same problem that belu reports
* Soundbridge reports 99% WiFi signal, and WMP streams WAVs OK, so the connection is not suspect.
* There is a machine B with a 100mbps wired connection, connection tested using FTP transfers, line speed known to be good.

Observations:
* FF streaming a file locally (wget http://localhost:9999/rsp/stream/7254) runs at 3.6 M/Sec, no pauses.
* FF streaming to machine B gets me 160K/s, not enough to serve uncompressed audio.
* FF streaming to machine B via an SSH tunnel to machine A gets me a respectable 1.8 M/Sec

It appears to me that, for some reason, FF streams very slowly to the network interface, at least compared to the speed when streaming to the local interface.

After rolling back to 1586, I get 5M/s+ on both the local and the remote interface.

Can anyone recreate the above test? Any other testing/information that I may provide?

Thanks,

Michael

That’s gotta be the select polling. Gack. I wanted a uniform way of selecting for both files and sockets for windows, but WaitForMultipleObjects won’t wait on a socket. Grumble…

I might just turn that into select on sockets, as I don’t ever wait on mixed file and socket descriptors, but dang… that just kinda ticks me off.

I’ll play with it. I really thought it was fixed, though.

[Author]

Posts