Bug 2777 - alarm clock not working
: alarm clock not working
Status: CLOSED FIXED
Product: SB 1
Classification: Unclassified
Component: Firmware
: 40
: Macintosh MacOS X 10.4
: P2 normal (vote)
: Future
Assigned To: Blackketter Dean
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2006-01-03 07:40 UTC by Julius Friede
Modified: 2008-12-15 13:05 UTC (History)
1 user (show)

See Also:
Category: ---


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Julius Friede 2006-01-03 07:40:26 UTC
The everyday alarm clock is not working very well. In 2005 it worked normally on weekdays and didn�t on weekends. It hasn�t worked at all yet in 2006. The symptoms: the playlist is loaded at the proper time and starts to play (looking at the web interface) but restarts playing before any sound is generated. Power cycling the player immediately starts playing the list as soon as the player configures itself. In 2005 this happened with multiple SB�s, although i haven�t switched players yet this year. I am currently using this build of the server, SlimServer Version: 6.2.2 - 5448 - Mac OS X 10.4.3 (8F46) - EN - utf8 (12/30/05), although this problem also affected earlier builds. I am using the Fishbone skin. Below is a log with d_slimproto and d_source enabled. Sorry in advance that it is as long as it is. This bug is not the same as Bug 2258 i had submitted in the past. That was corrected and all was working normally up until a few weeks ago when this started up. I have also replaced my preference file if that is of any consequence. Also, I have been communicating with Kevin at SD about this, but I felt this might benefit others with a similar problem if I make it an official bug report.

2006-01-03 06:00:08.8778 00:04:20:05:76:a8: Switching to mode stop from pause
2006-01-03 06:00:08.8792 00:04:20:05:76:a8 New play mode: stop
2006-01-03 06:00:08.8798 Stopping and clearing out old chunks for client 00:04:20:05:76:a8
2006-01-03 06:00:08.8806 *************stream called: q paused:  format:  url: 
2006-01-03 06:00:08.8813 Backtrace:

   frame 0: Slim::Player::Squeezebox::stream (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Squeezebox.pm line 196)
   frame 1: Slim::Player::Squeezebox::stop (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Source.pm line 475)
   frame 2: Slim::Player::Source::playmode (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Control/Command.pm line 301)
   frame 3: Slim::Control::Command::execute (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Client.pm line 996)
   frame 4: Slim::Player::Client::execute (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Buttons/AlarmClock.pm line 343)
   frame 5: Slim::Buttons::AlarmClock::checkAlarms (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Utils/Timers.pm line 105)
   frame 6: Slim::Utils::Timers::checkTimers (./slimserver.pl line 639)
   frame 7: main::idle (./slimserver.pl line 570)
   frame 8: main::main (./slimserver.pl line 1226)

2006-01-03 06:00:08.8821 starting with decoder with format: m autostart: 0 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ?
2006-01-03 06:00:08.8824 flags: 0
2006-01-03 06:00:08.8827 sending strm frame of length: 76 request string:
GET /stream.mp3?player=00:04:20:05:76:a8 HTTP/1.0



2006-01-03 06:00:08.8844 Resetting song queue
2006-01-03 06:00:08.8849 Song queue is now 0
2006-01-03 06:00:08.8857 00:04:20:05:76:a8: Current playmode: stop
2006-01-03 06:00:08.8972 00:04:20:05:76:a8: Switching to mode stop from stop
2006-01-03 06:00:08.8979  Already in playmode stop : ignoring mode change
2006-01-03 06:00:35.3313 00:04:20:05:76:a8: Switching to mode stop from stop
2006-01-03 06:00:35.3320  Already in playmode stop : ignoring mode change
2006-01-03 06:00:35.3356 Adding song index 0 to song queue
2006-01-03 06:00:35.3363 Clearing out song queue first
2006-01-03 06:00:35.3367 Song queue is now 0
2006-01-03 06:00:35.3606 00:04:20:05:76:a8: Switching to mode stop from stop
2006-01-03 06:00:35.3612  Already in playmode stop : ignoring mode change
2006-01-03 06:00:35.3616 Adding song index 0 to song queue
2006-01-03 06:00:35.3619 Clearing out song queue first
2006-01-03 06:00:35.3621 Song queue is now 0
2006-01-03 06:00:35.3628 00:04:20:05:76:a8: Switching to mode play from stop
2006-01-03 06:00:35.3651 openSong on: file:///Volumes/BirdSong/Music/Sam%20Phillips/Martinis%20%26%20Bikinis/Black%20Sky.mp3
2006-01-03 06:00:35.3717 openSong: getting duration  244.453, size 6247550, endian  and offset 2386 for file:///Volumes/BirdSong/Music/Sam%20Phillips/Martinis%20%26%20Bikinis/Black%20Sky.mp3
2006-01-03 06:00:35.3729 Setting maxBitRate for Master Bedroom to: 0
2006-01-03 06:00:35.3735 Setting maxBitRate for Master Bedroom to: 0
2006-01-03 06:00:35.3906 Setting maxBitRate for Master Bedroom to: 0
2006-01-03 06:00:35.3914 Setting maxBitRate for Master Bedroom to: 0
2006-01-03 06:00:35.3918 undermax = 1, type = mp3, squeezebox = 00:04:20:05:76:a8, lame = /Users/juliusf/Library/iTunes/Scripts/iTunes-LAME.app/Contents/Resources/lame
2006-01-03 06:00:35.3923 checking formats for: mp3-aif-squeezebox-00:04:20:05:76:a8
2006-01-03 06:00:35.3926 checking formats for: mp3-aif-*-00:04:20:05:76:a8
2006-01-03 06:00:35.3935 checking formats for: mp3-aif-squeezebox-*
2006-01-03 06:00:35.3937 checking formats for: mp3-aif-*-*
2006-01-03 06:00:35.3940 checking formats for: mp3-wav-squeezebox-00:04:20:05:76:a8
2006-01-03 06:00:35.3941 checking formats for: mp3-wav-*-00:04:20:05:76:a8
2006-01-03 06:00:35.3957 checking formats for: mp3-wav-squeezebox-*
2006-01-03 06:00:35.3960 checking formats for: mp3-wav-*-*
2006-01-03 06:00:35.3963 checking formats for: mp3-mp3-squeezebox-00:04:20:05:76:a8
2006-01-03 06:00:35.3965 checking formats for: mp3-mp3-*-00:04:20:05:76:a8
2006-01-03 06:00:35.3966 checking formats for: mp3-mp3-squeezebox-*
2006-01-03 06:00:35.3968 checking formats for: mp3-mp3-*-*
2006-01-03 06:00:35.3969 Checking to see if mp3-mp3-*-* is enabled
2006-01-03 06:00:35.3970    enabled
2006-01-03 06:00:35.3971   Found command: -
2006-01-03 06:00:35.3978 Setting maxBitRate for Master Bedroom to: 0
2006-01-03 06:00:35.3983 Setting maxBitRate for Master Bedroom to: 0
2006-01-03 06:00:35.3985 Matched Format: mp3 Type: mp3 Command: - 
2006-01-03 06:00:35.3987 openSong: this is an mp3 file: file:///Volumes/BirdSong/Music/Sam%20Phillips/Martinis%20%26%20Bikinis/Black%20Sky.mp3
2006-01-03 06:00:35.3989   file type: mp3 format: mp3 inrate: 204 maxRate: 0
2006-01-03 06:00:35.3991   command: -
2006-01-03 06:00:35.3995 openSong: opening file /Volumes/BirdSong/Music/Sam Phillips/Martinis & Bikinis/Black Sky.mp3
2006-01-03 06:00:35.4001  seeking in 2386 into /Volumes/BirdSong/Music/Sam Phillips/Martinis & Bikinis/Black Sky.mp3
2006-01-03 06:00:35.4008 Streaming with format: mp3
2006-01-03 06:00:35.4634 00:04:20:05:76:a8 New play mode: play
2006-01-03 06:00:35.4683 00:04:20:05:76:a8: Current playmode: play
2006-01-03 06:00:35.8535 Slimproto connection closed by peer in readable.
2006-01-03 06:00:35.8541 Slimproto connection closed
2006-01-03 06:00:35.8551 Slimproto connection closed by peer in readable.
2006-01-03 06:00:35.8554 Slimproto connection closed
2006-01-03 06:00:35.8560 Slimproto connection closed by peer in readable.
2006-01-03 06:00:35.8562 Slimproto connection closed
2006-01-03 06:00:35.8606 Slimproto connection closed by peer in readable.
2006-01-03 06:00:35.8612 Slimproto connection closed
2006-01-03 06:00:35.8621 Slimproto connection closed by peer in readable.
2006-01-03 06:00:35.8624 Slimproto connection closed
2006-01-03 06:00:35.8640 Slimproto accepted connection from: 192.168.2.101
2006-01-03 06:00:35.8725 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x7171b54)
2006-01-03 06:00:35.8733 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:10:16
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 07ff
2006-01-03 06:00:35.8740 hello from existing client: 00:04:20:05:10:16 on ipport: 192.168.2.101:32738
2006-01-03 06:00:35.8838 Slimproto accepted connection from: 192.168.2.85
2006-01-03 06:00:35.8885 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x71e2858)
2006-01-03 06:00:35.8892 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:3a:8e
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-03 06:00:35.8904 hello from existing client: 00:04:20:05:3a:8e on ipport: 192.168.2.85:53281
2006-01-03 06:00:35.8983 Slimproto accepted connection from: 192.168.2.102
2006-01-03 06:00:35.9017 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x715f290)
2006-01-03 06:00:35.9024 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:76:a8
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-03 06:00:35.9030 hello from existing client: 00:04:20:05:76:a8 on ipport: 192.168.2.102:41430
2006-01-03 06:00:35.9091 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x7171b54)
2006-01-03 06:00:35.9112 00:04:20:05:10:16 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-03 06:00:35.9155 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x71e2858)
2006-01-03 06:00:35.9164 00:04:20:05:3a:8e Squeezebox stream status:
	fullness:        6 (0%)
	bytes_received   12176042
2006-01-03 06:00:35.9314 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x715f290)
2006-01-03 06:00:35.9324 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-03 06:00:57.8619 Slimproto connection closed by peer in readable.
2006-01-03 06:00:57.8633 Slimproto connection closed
2006-01-03 06:00:57.8732 Slimproto accepted connection from: 192.168.2.102
2006-01-03 06:00:57.8776 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x2876e0)
2006-01-03 06:00:57.8784 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:76:a8
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-03 06:00:57.8791 hello from existing client: 00:04:20:05:76:a8 on ipport: 192.168.2.102:41431
2006-01-03 06:00:57.9164 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x2876e0)
2006-01-03 06:00:57.9187 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-03 06:21:18.0918 Requesting web page to keep SlimServer unswapped, re-request interval is 30 minutes.
2006-01-03 06:22:02.3294 Slimproto connection closed by peer in readable.
2006-01-03 06:22:02.3367 Slimproto connection closed
2006-01-03 06:22:02.3378 Slimproto connection closed by peer in readable.
2006-01-03 06:22:02.3381 Slimproto connection closed
2006-01-03 06:22:02.3387 Slimproto connection closed by peer in readable.
2006-01-03 06:22:02.3389 Slimproto connection closed
2006-01-03 06:22:02.5804 Slimproto accepted connection from: 192.168.2.102
2006-01-03 06:22:02.6198 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x71ee490)
2006-01-03 06:22:02.6205 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:76:a8
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-03 06:22:02.6212 hello from existing client: 00:04:20:05:76:a8 on ipport: 192.168.2.102:41434
2006-01-03 06:22:02.6389 Slimproto accepted connection from: 192.168.2.101
2006-01-03 06:22:02.6954 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x71bcf08)
2006-01-03 06:22:02.6963 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:10:16
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 07ff
2006-01-03 06:22:02.6979 hello from existing client: 00:04:20:05:10:16 on ipport: 192.168.2.101:32741
2006-01-03 06:22:02.7054 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x71ee490)
2006-01-03 06:22:02.7065 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-03 06:22:02.7084 Slimproto accepted connection from: 192.168.2.85
2006-01-03 06:22:02.7418 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x71bce0c)
2006-01-03 06:22:02.7426 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:3a:8e
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-03 06:22:02.7432 hello from existing client: 00:04:20:05:3a:8e on ipport: 192.168.2.85:53284
2006-01-03 06:22:02.7507 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x71bcf08)
2006-01-03 06:22:02.7516 00:04:20:05:10:16 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-03 06:22:02.7844 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x71bce0c)
2006-01-03 06:22:02.7860 00:04:20:05:3a:8e Squeezebox stream status:
	fullness:        6 (0%)
	bytes_received   12176042
2006-01-03 06:51:18.1135 Requesting web page to keep SlimServer unswapped, re-request interval is 30 minutes.
2006-01-03 06:52:02.2246 Slimproto connection closed by peer in readable.
2006-01-03 06:52:02.2318 Slimproto connection closed
2006-01-03 06:52:02.2329 Slimproto connection closed by peer in readable.
2006-01-03 06:52:02.2332 Slimproto connection closed
2006-01-03 06:52:02.2340 Slimproto connection closed by peer in readable.
2006-01-03 06:52:02.2342 Slimproto connection closed
2006-01-03 06:52:02.4691 Slimproto accepted connection from: 192.168.2.102
2006-01-03 06:52:02.5056 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x71bc9b4)
2006-01-03 06:52:02.5080 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:76:a8
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-03 06:52:02.5094 hello from existing client: 00:04:20:05:76:a8 on ipport: 192.168.2.102:41437
2006-01-03 06:52:02.5333 Slimproto accepted connection from: 192.168.2.101
2006-01-03 06:52:02.5790 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x71e4630)
2006-01-03 06:52:02.5824 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:10:16
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 07ff
2006-01-03 06:52:02.5832 hello from existing client: 00:04:20:05:10:16 on ipport: 192.168.2.101:32744
2006-01-03 06:52:02.5914 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x71bc9b4)
2006-01-03 06:52:02.5924 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-03 06:52:02.5943 Slimproto accepted connection from: 192.168.2.85
2006-01-03 06:52:02.6286 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x641620)
2006-01-03 06:52:02.6301 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:3a:8e
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-03 06:52:02.6309 hello from existing client: 00:04:20:05:3a:8e on ipport: 192.168.2.85:53287
2006-01-03 06:52:02.6381 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x71e4630)
2006-01-03 06:52:02.6393 00:04:20:05:10:16 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-03 06:52:02.6722 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x641620)
2006-01-03 06:52:02.6735 00:04:20:05:3a:8e Squeezebox stream status:
	fullness:        6 (0%)
	bytes_received   12176042
2006-01-03 07:10:04.3996 Slimproto connection closed by peer in readable.
2006-01-03 07:10:04.4093 Slimproto connection closed
2006-01-03 07:10:04.4104 Slimproto connection closed by peer in readable.
2006-01-03 07:10:04.4108 Slimproto connection closed
2006-01-03 07:10:04.4114 Slimproto connection closed by peer in readable.
2006-01-03 07:10:04.4116 Slimproto connection closed
2006-01-03 07:10:04.4405 Slimproto accepted connection from: 192.168.2.102
2006-01-03 07:10:04.4472 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x71bce9c)
2006-01-03 07:10:04.4481 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:76:a8
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-03 07:10:04.4488 hello from existing client: 00:04:20:05:76:a8 on ipport: 192.168.2.102:41439
2006-01-03 07:10:04.4633 Slimproto accepted connection from: 192.168.2.85
2006-01-03 07:10:04.4659 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x71c4824)
2006-01-03 07:10:04.4665 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:3a:8e
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-03 07:10:04.4672 hello from existing client: 00:04:20:05:3a:8e on ipport: 192.168.2.85:53289
2006-01-03 07:10:04.4754 Slimproto accepted connection from: 192.168.2.101
2006-01-03 07:10:04.4771 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x71dd28)
2006-01-03 07:10:04.4777 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:10:16
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 07ff
2006-01-03 07:10:04.4784 hello from existing client: 00:04:20:05:10:16 on ipport: 192.168.2.101:32746
2006-01-03 07:10:04.5026 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x71dd28)
2006-01-03 07:10:04.5050 00:04:20:05:10:16 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-03 07:10:04.5064 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x71bce9c)
2006-01-03 07:10:04.5071 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-03 07:10:04.5086 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x71c4824)
2006-01-03 07:10:04.5093 00:04:20:05:3a:8e Squeezebox stream status:
	fullness:        6 (0%)
	bytes_received   12176042
2006-01-03 07:10:51.2352 Slimproto connection closed by peer in readable.
2006-01-03 07:10:51.2470 Slimproto connection closed
2006-01-03 07:10:51.2481 Slimproto connection closed by peer in readable.
2006-01-03 07:10:51.2485 Slimproto connection closed
2006-01-03 07:10:51.2492 Slimproto connection closed by peer in readable.
2006-01-03 07:10:51.2495 Slimproto connection closed
2006-01-03 07:11:00.8989 Setting maxBitRate for Master Bedroom to: 0
2006-01-03 07:11:00.8998 Setting maxBitRate for Master Bedroom to: 0
2006-01-03 07:11:01.9682 Slimproto accepted connection from: 192.168.2.102
2006-01-03 07:11:01.9927 Slimproto accepted connection from: 192.168.2.101
2006-01-03 07:11:02.0111 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x640ce4)
2006-01-03 07:11:02.0119 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:10:16
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 07ff
2006-01-03 07:11:02.0135 hello from existing client: 00:04:20:05:10:16 on ipport: 192.168.2.101:32750
2006-01-03 07:11:02.0201 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x5467398)
2006-01-03 07:11:02.0208 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:76:a8
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-03 07:11:02.0215 hello from existing client: 00:04:20:05:76:a8 on ipport: 192.168.2.102:41443
2006-01-03 07:11:02.0399 Slimproto accepted connection from: 192.168.2.85
2006-01-03 07:11:02.2681 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x6275a8)
2006-01-03 07:11:02.2692 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:3a:8e
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-03 07:11:02.2699 hello from existing client: 00:04:20:05:3a:8e on ipport: 192.168.2.85:53293
2006-01-03 07:11:02.2773 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x640ce4)
2006-01-03 07:11:02.2793 00:04:20:05:10:16 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-03 07:11:02.2811 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x5467398)
2006-01-03 07:11:02.2819 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-03 07:11:02.4931 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x6275a8)
2006-01-03 07:11:02.4943 00:04:20:05:3a:8e Squeezebox stream status:
	fullness:        6 (0%)
	bytes_received   12176042
2006-01-03 07:11:34.6484 Setting maxBitRate for Master Bedroom to: 0
2006-01-03 07:11:34.6503 Setting maxBitRate for Master Bedroom to: 0
Comment 1 KDF 2006-01-04 14:19:24 UTC
From the parts of the log that are from d_source, it looks like the alarm isn't the problem. The event triggers, and playback is initiated properly. From the OpenSong onward, the behaviour would be the same as if you pressed PLAY

from this line:
2006-01-03 06:00:35.4001  seeking in 2386 into /Volumes/BirdSong/Music/Sam
Phillips/Martinis & Bikinis/Black Sky.mp3

I get the impression that this is a file referenced by a cue sheet?  
the slimproto log makes it seem as if the squeezebox itself is dropping out and reconnecting. Do you have this kind of problem if you try to manually play this track after some length of idle time?  Do you leave the player running with the RSS screensaver overnight, perhaps? Could this be wome sort of wireless dropout?
Comment 2 Julius Friede 2006-01-04 23:25:56 UTC
I am not using a cue sheet, just the random song plugin and iTunes. The specific song that day was just that day�s random selection. All first songs act this way. I will try a normal playlist today and see what happens. I do not use the RSS screensaver, mostly the player is off until the alarm time. All songs play fine if I just play them directly. I had thought it was a SB player problem, but multiple SBs act this way. This makes me believe it is the server. The SB associated with the previous log was connected wirelessly, but the same thing happens with a wired connection. As I mentioned previously, everything was working just fine until about December when it stopped working on Sundays and occasionally Saturdays. As of 2006 it never works. Very strange.
Comment 3 KDF 2006-01-04 23:39:35 UTC
yes, very strange.  which is why I am grasping a bit.  are you able to initiate a random playback manually without problems?

am I to understand that you have been working with the same nightly build during this time, or have you been updating daily?  If you have updated, perhaps regress to a version of around Dec 26 (6.2.2 was quiet for much of the days leading up to that, and a few new things have gone in since)

Thanks for your patience, while I whittle down the possible issues :)
Comment 4 Julius Friede 2006-01-05 06:33:49 UTC
For the most part I was using the 12/11 build, but I have also tried the 12/30 and  1/4/06 build. FWIW, I tried selecting a normal playlist instead of random song and it worked perfectly. When I return from work today I will try manually selecting random mix and see what happens.
Comment 5 Julius Friede 2006-01-06 06:21:31 UTC
Manually selecting random mix works fine. A second standard playlist also works fine with the alarm. It seems that there is an issue with the alarm, random mix plugin, and possibly something else (Fishbone skin, Mac OSX?) combination.
Comment 6 Julius Friede 2006-01-10 08:23:54 UTC
I downloaded the 1/10 build and tried random mix with the alarm clock again. I don�t know if any changes have been made specifically for this problem or if this is an intermittant instance, but the combination worked today. I�ll continue to monitor it.
Comment 7 Julius Friede 2006-01-12 06:54:20 UTC
using the same 1/10 build, the problem was back this morning. The only things different today from yesterday are: Thursday instead of Wednesday, during the night there was an automatic backup of my system to another drive that was preceded by a permissions reset. I have the log if you want it and I will try the latest build unless you suggest I stay with this build.
Comment 8 KDF 2006-01-12 09:25:54 UTC
Please do attach the log files.  I have no ideas left as to the cause.  I use the plugin alarm every morning on random and have never had this kind of problem.  Other difference is that I use 6.5.
Comment 9 Julius Friede 2006-01-12 19:41:17 UTC
I certainly share your puzzlement as to the cause of this problem. It was working regularly for me for a long while when this started malfunctioning. I installed the 1/12 build this morning and will see if that has a positive impact. BTW, how stable are the current 6.5 builds? 

log follows:

2006-01-12 06:00:39.5741 00:04:20:05:76:a8: Switching to mode stop from pause
2006-01-12 06:00:40.0832 00:04:20:05:76:a8 New play mode: stop
2006-01-12 06:00:40.0843 Stopping and clearing out old chunks for client 00:04:20:05:76:a8
2006-01-12 06:00:40.0855 *************stream called: q paused:  format:  url: 
2006-01-12 06:00:40.0863 Backtrace:

   frame 0: Slim::Player::Squeezebox::stream (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Squeezebox.pm line 196)
   frame 1: Slim::Player::Squeezebox::stop (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Source.pm line 475)
   frame 2: Slim::Player::Source::playmode (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Control/Command.pm line 301)
   frame 3: Slim::Control::Command::execute (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Client.pm line 996)
   frame 4: Slim::Player::Client::execute (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Buttons/AlarmClock.pm line 343)
   frame 5: Slim::Buttons::AlarmClock::checkAlarms (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Utils/Timers.pm line 105)
   frame 6: Slim::Utils::Timers::checkTimers (./slimserver.pl line 639)
   frame 7: main::idle (./slimserver.pl line 570)
   frame 8: main::main (./slimserver.pl line 1226)

2006-01-12 06:00:40.0871 starting with decoder with format: m autostart: 0 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ?
2006-01-12 06:00:40.0877 flags: 0
2006-01-12 06:00:40.0881 sending strm frame of length: 76 request string:
GET /stream.mp3?player=00:04:20:05:76:a8 HTTP/1.0



2006-01-12 06:00:40.0901 Resetting song queue
2006-01-12 06:00:40.0908 Song queue is now 0
2006-01-12 06:00:40.0926 00:04:20:05:76:a8: Current playmode: stop
2006-01-12 06:00:40.1053 RandomPlay: received command stop
2006-01-12 06:00:40.1062 RandomPlay: while in mode: track, from Master Bedroom
2006-01-12 06:00:40.1089 RandomPlay: received command mixer volume 100
2006-01-12 06:00:40.1098 RandomPlay: while in mode: track, from Master Bedroom
2006-01-12 06:00:40.1217 RandomPlay: playRandom called with type track
2006-01-12 06:00:40.1235 RandomPlay: 9 songs remaining, songIndex = 0
2006-01-12 06:00:40.1244 00:04:20:05:76:a8: Switching to mode stop from stop
2006-01-12 06:00:40.1249  Already in playmode stop : ignoring mode change
2006-01-12 06:00:40.1883 RandomPlay: Starting random selection of 10 items for type: track
2006-01-12 06:01:14.3779 RandomPlay: Find returned 10 items
2006-01-12 06:01:14.3922 RandomPlay: Playing track: Lie To Me, 11812
2006-01-12 06:01:14.3942 00:04:20:05:76:a8: Switching to mode stop from stop
2006-01-12 06:01:14.3949  Already in playmode stop : ignoring mode change
2006-01-12 06:01:14.3963 Adding song index 0 to song queue
2006-01-12 06:01:14.3969 Clearing out song queue first
2006-01-12 06:01:14.3978 Song queue is now 0
2006-01-12 06:01:14.4284 00:04:20:05:76:a8: Switching to mode stop from stop
2006-01-12 06:01:14.4293  Already in playmode stop : ignoring mode change
2006-01-12 06:01:14.4301 Adding song index 0 to song queue
2006-01-12 06:01:14.4305 Clearing out song queue first
2006-01-12 06:01:14.4311 Song queue is now 0
2006-01-12 06:01:14.4320 00:04:20:05:76:a8: Switching to mode play from stop
2006-01-12 06:01:14.4348 openSong on: file:///Volumes/BirdSong/Music/Kaleidoscope/Egyptian%20Candy/Lie%20To%20Me.mp3
2006-01-12 06:01:14.4427 openSong: getting duration  167.758, size 5365777, endian  and offset 580 for file:///Volumes/BirdSong/Music/Kaleidoscope/Egyptian%20Candy/Lie%20To%20Me.mp3
2006-01-12 06:01:14.4449 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:01:14.4459 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:01:14.4844 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:01:14.4855 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:01:14.4863 undermax = 1, type = mp3, squeezebox = 00:04:20:05:76:a8, lame = /Users/juliusf/Library/iTunes/Scripts/iTunes-LAME.app/Contents/Resources/lame
2006-01-12 06:01:14.4874 checking formats for: mp3-aif-squeezebox-00:04:20:05:76:a8
2006-01-12 06:01:14.4881 checking formats for: mp3-aif-*-00:04:20:05:76:a8
2006-01-12 06:01:14.4885 checking formats for: mp3-aif-squeezebox-*
2006-01-12 06:01:14.4888 checking formats for: mp3-aif-*-*
2006-01-12 06:01:14.4891 checking formats for: mp3-wav-squeezebox-00:04:20:05:76:a8
2006-01-12 06:01:14.4894 checking formats for: mp3-wav-*-00:04:20:05:76:a8
2006-01-12 06:01:14.4897 checking formats for: mp3-wav-squeezebox-*
2006-01-12 06:01:14.4899 checking formats for: mp3-wav-*-*
2006-01-12 06:01:14.4902 checking formats for: mp3-mp3-squeezebox-00:04:20:05:76:a8
2006-01-12 06:01:14.4905 checking formats for: mp3-mp3-*-00:04:20:05:76:a8
2006-01-12 06:01:14.4907 checking formats for: mp3-mp3-squeezebox-*
2006-01-12 06:01:14.4909 checking formats for: mp3-mp3-*-*
2006-01-12 06:01:14.4913 Checking to see if mp3-mp3-*-* is enabled
2006-01-12 06:01:14.4917    enabled
2006-01-12 06:01:14.4921   Found command: -
2006-01-12 06:01:14.4929 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:01:14.4943 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:01:14.4949 Matched Format: mp3 Type: mp3 Command: - 
2006-01-12 06:01:14.4954 openSong: this is an mp3 file: file:///Volumes/BirdSong/Music/Kaleidoscope/Egyptian%20Candy/Lie%20To%20Me.mp3
2006-01-12 06:01:14.4958   file type: mp3 format: mp3 inrate: 255 maxRate: 0
2006-01-12 06:01:14.4961   command: -
2006-01-12 06:01:14.4968 openSong: opening file /Volumes/BirdSong/Music/Kaleidoscope/Egyptian Candy/Lie To Me.mp3
2006-01-12 06:01:14.4996  seeking in 580 into /Volumes/BirdSong/Music/Kaleidoscope/Egyptian Candy/Lie To Me.mp3
2006-01-12 06:01:14.5008 Streaming with format: mp3
2006-01-12 06:01:14.5907 00:04:20:05:76:a8 New play mode: play
2006-01-12 06:01:14.5971 00:04:20:05:76:a8: Current playmode: play
2006-01-12 06:01:14.8204 Adding 9 tracks to end of playlist
2006-01-12 06:01:14.9212 RandomPlay: Playing continuous track mode with 10 items
2006-01-12 06:01:14.9242 Slimproto connection closed by peer in readable.
2006-01-12 06:01:14.9249 Slimproto connection closed
2006-01-12 06:01:14.9260 Slimproto connection closed by peer in readable.
2006-01-12 06:01:14.9265 Slimproto connection closed
2006-01-12 06:01:14.9279 Slimproto connection closed by peer in readable.
2006-01-12 06:01:14.9284 Slimproto connection closed
2006-01-12 06:01:14.9481 Slimproto accepted connection from: 192.168.2.85
2006-01-12 06:01:14.9517 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x57c740c)
2006-01-12 06:01:14.9525 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:3a:8e
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-12 06:01:14.9535 hello from existing client: 00:04:20:05:3a:8e on ipport: 192.168.2.85:53989
2006-01-12 06:01:14.9618 Slimproto accepted connection from: 192.168.2.101
2006-01-12 06:01:14.9682 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x7033374)
2006-01-12 06:01:14.9696 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:10:16
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 07ff
2006-01-12 06:01:14.9705 hello from existing client: 00:04:20:05:10:16 on ipport: 192.168.2.101:33330
2006-01-12 06:01:14.9797 Slimproto accepted connection from: 192.168.2.102
2006-01-12 06:01:15.0973 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x57e2d3c)
2006-01-12 06:01:15.0983 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:76:a8
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-12 06:01:15.0993 hello from existing client: 00:04:20:05:76:a8 on ipport: 192.168.2.102:43033
2006-01-12 06:01:15.1072 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x7033374)
2006-01-12 06:01:15.1084 00:04:20:05:10:16 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:01:15.1098 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x57c740c)
2006-01-12 06:01:15.1109 00:04:20:05:3a:8e Squeezebox stream status:
	fullness:        6 (0%)
	bytes_received   12176042
2006-01-12 06:01:15.1248 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x57e2d3c)
2006-01-12 06:01:15.1261 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:01:36.9322 Slimproto connection closed by peer in readable.
2006-01-12 06:01:37.3527 Slimproto connection closed
2006-01-12 06:01:37.3611 Slimproto accepted connection from: 192.168.2.102
2006-01-12 06:01:37.3685 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x5b1b488)
2006-01-12 06:01:37.3705 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:76:a8
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-12 06:01:37.3720 hello from existing client: 00:04:20:05:76:a8 on ipport: 192.168.2.102:43034
2006-01-12 06:01:37.4305 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x5b1b488)
2006-01-12 06:01:37.4318 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:18:54.3601 Requesting web page to keep SlimServer unswapped, re-request interval is 30 minutes.
2006-01-12 06:19:36.6493 Slimproto connection closed by peer in readable.
2006-01-12 06:19:36.6614 Slimproto connection closed
2006-01-12 06:19:36.6628 Slimproto connection closed by peer in readable.
2006-01-12 06:19:36.6633 Slimproto connection closed
2006-01-12 06:19:36.6642 Slimproto connection closed by peer in readable.
2006-01-12 06:19:36.6646 Slimproto connection closed
2006-01-12 06:19:36.9053 Slimproto accepted connection from: 192.168.2.85
2006-01-12 06:19:36.9374 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x7017e94)
2006-01-12 06:19:36.9389 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:3a:8e
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-12 06:19:36.9399 hello from existing client: 00:04:20:05:3a:8e on ipport: 192.168.2.85:53992
2006-01-12 06:19:36.9485 Slimproto accepted connection from: 192.168.2.101
2006-01-12 06:19:36.9912 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x700ce88)
2006-01-12 06:19:36.9923 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:10:16
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 07ff
2006-01-12 06:19:36.9943 hello from existing client: 00:04:20:05:10:16 on ipport: 192.168.2.101:33333
2006-01-12 06:19:37.0024 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x7017e94)
2006-01-12 06:19:37.0050 00:04:20:05:3a:8e Squeezebox stream status:
	fullness:        6 (0%)
	bytes_received   12176042
2006-01-12 06:19:37.0074 Slimproto accepted connection from: 192.168.2.102
2006-01-12 06:19:37.0404 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x704a9b0)
2006-01-12 06:19:37.0416 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:76:a8
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-12 06:19:37.0425 hello from existing client: 00:04:20:05:76:a8 on ipport: 192.168.2.102:43037
2006-01-12 06:19:37.0594 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x700ce88)
2006-01-12 06:19:37.0606 00:04:20:05:10:16 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:19:37.0973 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x704a9b0)
2006-01-12 06:19:37.0986 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:34.1641 Slimproto accepted connection from: 192.168.2.102
2006-01-12 06:24:34.6760 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:34.6776 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:76:a8
	bitmapped: 32768
	reconnect: 0
	wlan_channellist: 0000
2006-01-12 06:24:34.6786 hello from existing client: 00:04:20:05:76:a8 on ipport: 192.168.2.102:43477
2006-01-12 06:24:34.6799 00:04:20:05:76:a8: Switching to mode stop from play
2006-01-12 06:24:34.6805 00:04:20:05:76:a8 New play mode: stop
2006-01-12 06:24:34.6823 Stopping and clearing out old chunks for client 00:04:20:05:76:a8
2006-01-12 06:24:34.6838 *************stream called: q paused:  format:  url: 
2006-01-12 06:24:34.6849 Backtrace:

   frame 0: Slim::Player::Squeezebox::stream (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Squeezebox.pm line 196)
   frame 1: Slim::Player::Squeezebox::stop (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Source.pm line 475)
   frame 2: Slim::Player::Source::playmode (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Squeezebox.pm line 87)
   frame 3: Slim::Player::Squeezebox::reconnect (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Networking/Slimproto.pm line 348)
   frame 4: Slim::Networking::Slimproto::process_slimproto_frame (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Networking/Slimproto.pm line 244)
   frame 5: Slim::Networking::Slimproto::client_readable (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Networking/Select.pm line 111)
   frame 6: Slim::Networking::Select::select (./slimserver.pl line 634)
   frame 7: main::idle (./slimserver.pl line 570)
   frame 8: main::main (./slimserver.pl line 1226)

2006-01-12 06:24:34.6857 starting with decoder with format: m autostart: 0 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ?
2006-01-12 06:24:34.6862 flags: 0
2006-01-12 06:24:34.6866 sending strm frame of length: 76 request string:
GET /stream.mp3?player=00:04:20:05:76:a8 HTTP/1.0



2006-01-12 06:24:34.6888 Resetting song queue
2006-01-12 06:24:34.6896 Song queue is now 0
2006-01-12 06:24:34.6909 00:04:20:05:76:a8: Current playmode: stop
2006-01-12 06:24:34.6916 00:04:20:05:76:a8: Switching to mode play from stop
2006-01-12 06:24:34.6929 openSong on: file:///Volumes/BirdSong/Music/Kaleidoscope/Egyptian%20Candy/Lie%20To%20Me.mp3
2006-01-12 06:24:34.6974 openSong: getting duration  167.758, size 5365777, endian  and offset 580 for file:///Volumes/BirdSong/Music/Kaleidoscope/Egyptian%20Candy/Lie%20To%20Me.mp3
2006-01-12 06:24:34.6988 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:24:34.6998 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:24:34.7032 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:24:34.7042 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:24:34.7048 undermax = 1, type = mp3, squeezebox = 00:04:20:05:76:a8, lame = /Users/juliusf/Library/iTunes/Scripts/iTunes-LAME.app/Contents/Resources/lame
2006-01-12 06:24:34.7058 checking formats for: mp3-aif-squeezebox-00:04:20:05:76:a8
2006-01-12 06:24:34.7063 checking formats for: mp3-aif-*-00:04:20:05:76:a8
2006-01-12 06:24:34.7068 checking formats for: mp3-aif-squeezebox-*
2006-01-12 06:24:34.7078 checking formats for: mp3-aif-*-*
2006-01-12 06:24:34.7082 checking formats for: mp3-wav-squeezebox-00:04:20:05:76:a8
2006-01-12 06:24:34.7085 checking formats for: mp3-wav-*-00:04:20:05:76:a8
2006-01-12 06:24:34.7089 checking formats for: mp3-wav-squeezebox-*
2006-01-12 06:24:34.7092 checking formats for: mp3-wav-*-*
2006-01-12 06:24:34.7095 checking formats for: mp3-mp3-squeezebox-00:04:20:05:76:a8
2006-01-12 06:24:34.7098 checking formats for: mp3-mp3-*-00:04:20:05:76:a8
2006-01-12 06:24:34.7101 checking formats for: mp3-mp3-squeezebox-*
2006-01-12 06:24:34.7103 checking formats for: mp3-mp3-*-*
2006-01-12 06:24:34.7106 Checking to see if mp3-mp3-*-* is enabled
2006-01-12 06:24:34.7108    enabled
2006-01-12 06:24:34.7111   Found command: -
2006-01-12 06:24:34.7118 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:24:34.7125 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:24:34.7130 Matched Format: mp3 Type: mp3 Command: - 
2006-01-12 06:24:34.7134 openSong: this is an mp3 file: file:///Volumes/BirdSong/Music/Kaleidoscope/Egyptian%20Candy/Lie%20To%20Me.mp3
2006-01-12 06:24:34.7137   file type: mp3 format: mp3 inrate: 255 maxRate: 0
2006-01-12 06:24:34.7144   command: -
2006-01-12 06:24:34.7150 openSong: opening file /Volumes/BirdSong/Music/Kaleidoscope/Egyptian Candy/Lie To Me.mp3
2006-01-12 06:24:34.7157  seeking in 580 into /Volumes/BirdSong/Music/Kaleidoscope/Egyptian Candy/Lie To Me.mp3
2006-01-12 06:24:34.7164 Streaming with format: mp3
2006-01-12 06:24:34.8612 RandomPlay: received command newsong
2006-01-12 06:24:34.8624 RandomPlay: while in mode: track, from Master Bedroom
2006-01-12 06:24:34.8643 RandomPlay: new song detected (0)
2006-01-12 06:24:34.8650 RandomPlay: playRandom called with type track
2006-01-12 06:24:34.8664 RandomPlay: 9 songs remaining, songIndex = 0
2006-01-12 06:24:34.8670 RandomPlay: 9 items remaining so not adding new track
2006-01-12 06:24:34.8674 RandomPlay: Playing continuous track mode with 10 items
2006-01-12 06:24:34.8690 RandomPlay: received command open file:///Volumes/BirdSong/Music/Kaleidoscope/Egyptian%20Candy/Lie%20To%20Me.mp3
2006-01-12 06:24:34.8698 RandomPlay: while in mode: track, from Master Bedroom
2006-01-12 06:24:34.8706 00:04:20:05:76:a8 New play mode: play
2006-01-12 06:24:34.8732 *************stream called: s paused:  format: mp3 url: file:///Volumes/BirdSong/Music/Kaleidoscope/Egyptian%20Candy/Lie%20To%20Me.mp3
2006-01-12 06:24:34.8742 Backtrace:

   frame 0: Slim::Player::Squeezebox::stream (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Squeezebox.pm line 148)
   frame 1: Slim::Player::Squeezebox::play (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Source.pm line 495)
   frame 2: Slim::Player::Source::playmode (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Squeezebox.pm line 90)
   frame 3: Slim::Player::Squeezebox::reconnect (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Networking/Slimproto.pm line 348)
   frame 4: Slim::Networking::Slimproto::process_slimproto_frame (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Networking/Slimproto.pm line 244)
   frame 5: Slim::Networking::Slimproto::client_readable (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Networking/Select.pm line 111)
   frame 6: Slim::Networking::Select::select (./slimserver.pl line 634)
   frame 7: main::idle (./slimserver.pl line 570)
   frame 8: main::main (./slimserver.pl line 1226)

2006-01-12 06:24:34.8750 starting with decoder with format: m autostart: 1 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ?
2006-01-12 06:24:34.8756 flags: 0
2006-01-12 06:24:34.8760 sending strm frame of length: 76 request string:
GET /stream.mp3?player=00:04:20:05:76:a8 HTTP/1.0



2006-01-12 06:24:34.8796 00:04:20:05:76:a8: Current playmode: play
2006-01-12 06:24:34.8923 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:34.8937 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:34.8951 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:34.8962 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:34.8976 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:34.8992 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:34.9007 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:34.9016 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:34.9027 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:34.9034 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:34.9043 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:34.9054 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:34.9065 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:34.9075 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:34.9093 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:34.9103 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:34.9119 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:34.9128 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:34.9139 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:34.9239 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:34.9256 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:34.9265 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:34.9414 We need to send .25 seconds of silence...
2006-01-12 06:24:34.9711 sending 3140 bytes of silence
2006-01-12 06:24:34.9740 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:34.9765 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:43.2161 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:43.2409 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:24:43.2425 Got Slimproto frame, op RESP, length 136, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:43.2432 Squeezebox got HTTP response:
HTTP/1.0 200 OK
Date: Thu, 12 Jan 2006 14:24:34 GMT
Server: SlimServer (6.2.2 - 5597)
Connection: close
Content-Type: audio/mpeg


2006-01-12 06:24:43.2441 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:43.2450 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        3140 (1%)
	bytes_received   3140
2006-01-12 06:24:44.1566 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:44.1585 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        165198 (72%)
	bytes_received   165200
2006-01-12 06:24:44.2297 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:44.2313 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        171922 (74%)
	bytes_received   173960
2006-01-12 06:24:45.1759 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:45.1799 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228748 (99%)
	bytes_received   249880
2006-01-12 06:24:46.1755 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:46.1771 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        227976 (99%)
	bytes_received   280540
2006-01-12 06:24:47.1754 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:47.1767 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228640 (99%)
	bytes_received   309740
2006-01-12 06:24:48.1753 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:48.1766 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        227570 (99%)
	bytes_received   337480
2006-01-12 06:24:49.1793 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:49.1806 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        227076 (98%)
	bytes_received   368140
2006-01-12 06:24:50.1751 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:50.1767 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        227726 (99%)
	bytes_received   400260
2006-01-12 06:24:51.1748 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:51.1766 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228002 (99%)
	bytes_received   433840
2006-01-12 06:24:52.1746 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:52.1763 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228262 (99%)
	bytes_received   468880
2006-01-12 06:24:53.1783 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:53.1796 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        227322 (99%)
	bytes_received   499540
2006-01-12 06:24:54.1756 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:54.1769 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        227712 (99%)
	bytes_received   533120
2006-01-12 06:24:55.1745 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:55.1758 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228044 (99%)
	bytes_received   569620
2006-01-12 06:24:55.4332 Got Slimproto frame, op IR  , length 10, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:55.4388 RandomPlay: received command button  34.781 1
2006-01-12 06:24:55.4402 RandomPlay: while in mode: track, from Master Bedroom
2006-01-12 06:24:55.5319 Got Slimproto frame, op IR  , length 10, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:55.6402 Got Slimproto frame, op IR  , length 10, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:55.7481 Got Slimproto frame, op IR  , length 10, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:55.9694 00:04:20:05:76:a8: Switching to mode pause from play
2006-01-12 06:24:55.9705 00:04:20:05:76:a8 New play mode: pause
2006-01-12 06:24:55.9737 00:04:20:05:76:a8: Current playmode: pause
2006-01-12 06:24:55.9841 RandomPlay: received command pause
2006-01-12 06:24:55.9851 RandomPlay: while in mode: track, from Master Bedroom
2006-01-12 06:24:55.9944 RandomPlay: received command button pause 35.293 1
2006-01-12 06:24:55.9953 RandomPlay: while in mode: track, from Master Bedroom
2006-01-12 06:24:55.9981 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:55.9993 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228506 (99%)
	bytes_received   597360
2006-01-12 06:24:56.0386 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:56.0398 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228508 (99%)
	bytes_received   598820
2006-01-12 06:24:56.0887 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:56.0901 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228308 (99%)
	bytes_received   600280
2006-01-12 06:24:56.1424 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:56.1438 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228042 (99%)
	bytes_received   601740
2006-01-12 06:24:56.1757 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:56.1769 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228222 (99%)
	bytes_received   603200
2006-01-12 06:24:56.2111 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:56.2125 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228550 (99%)
	bytes_received   604660
2006-01-12 06:24:56.2571 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:56.2591 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228694 (99%)
	bytes_received   606120
2006-01-12 06:24:56.2951 *************stream called: p paused:  format:  url: 
2006-01-12 06:24:56.2961 Backtrace:

   frame 0: Slim::Player::Squeezebox::stream (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Squeezebox.pm line 186)
   frame 1: Slim::Player::Squeezebox::pause (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Source.pm line 2172)
   frame 2: Slim::Player::Source::pauseSynced (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Player/Player.pm line 1344)
   frame 3: Slim::Player::Player::fade_volume (/Users/juliusf/Library/PreferencePanes/SlimServer.prefPane/Contents/server/Slim/Utils/Timers.pm line 105)
   frame 4: Slim::Utils::Timers::checkTimers (./slimserver.pl line 639)
   frame 5: main::idle (./slimserver.pl line 570)
   frame 6: main::main (./slimserver.pl line 1226)

2006-01-12 06:24:56.2972 starting with decoder with format: m autostart: 0 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ?
2006-01-12 06:24:56.2977 flags: 0
2006-01-12 06:24:56.2993 sending strm frame of length: 76 request string:
GET /stream.mp3?player=00:04:20:05:76:a8 HTTP/1.0



2006-01-12 06:24:56.3114 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:56.3126 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        227168 (99%)
	bytes_received   606120
2006-01-12 06:24:56.3163 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:56.3174 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228344 (99%)
	bytes_received   607580
2006-01-12 06:24:56.3193 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:56.3203 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228344 (99%)
	bytes_received   607580
2006-01-12 06:24:56.3214 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:56.3222 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228344 (99%)
	bytes_received   607580
2006-01-12 06:24:56.4384 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:56.4406 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        228344 (99%)
	bytes_received   607580
2006-01-12 06:24:57.3734 Got Slimproto frame, op IR  , length 10, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:24:57.3879 RandomPlay: received command power
2006-01-12 06:24:57.3889 RandomPlay: while in mode: track, from Master Bedroom
2006-01-12 06:24:57.3898 RandomPlay: received command button power_toggle 36.73 1
2006-01-12 06:24:57.3904 RandomPlay: while in mode: track, from Master Bedroom
2006-01-12 06:24:57.4834 Got Slimproto frame, op IR  , length 10, IO::Socket::INET=GLOB(0x703f048)
2006-01-12 06:32:49.6212 Slimproto connection closed by peer in readable.
2006-01-12 06:32:49.6331 Slimproto connection closed
2006-01-12 06:39:02.0317 Slimproto accepted connection from: 192.168.2.85
2006-01-12 06:39:02.0462 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x57ce9d8)
2006-01-12 06:39:02.0473 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:3a:8e
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-12 06:39:02.0485 hello from existing client: 00:04:20:05:3a:8e on ipport: 192.168.2.85:53993
2006-01-12 06:39:17.0587 Slimproto accepted connection from: 192.168.2.102
2006-01-12 06:39:17.0654 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x7049178)
2006-01-12 06:39:17.0664 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:76:a8
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-12 06:39:17.0672 hello from existing client: 00:04:20:05:76:a8 on ipport: 192.168.2.102:43480
2006-01-12 06:39:18.2417 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x7049178)
2006-01-12 06:39:18.2430 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        229374 (99%)
	bytes_received   608610
2006-01-12 06:39:25.7428 Slimproto accepted connection from: 192.168.2.85
2006-01-12 06:39:31.0758 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x57db180)
2006-01-12 06:39:31.0775 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:3a:8e
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-12 06:39:31.0784 hello from existing client: 00:04:20:05:3a:8e on ipport: 192.168.2.85:53994
2006-01-12 06:39:31.1044 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x57db180)
2006-01-12 06:39:31.1056 00:04:20:05:3a:8e Squeezebox stream status:
	fullness:        6 (0%)
	bytes_received   12176042
2006-01-12 06:39:57.8881 Slimproto connection closed by peer in readable.
2006-01-12 06:39:57.8889 Slimproto connection closed
2006-01-12 06:39:57.8904 Slimproto connection closed by peer in readable.
2006-01-12 06:39:57.8909 Slimproto connection closed
2006-01-12 06:39:57.8929 Slimproto accepted connection from: 192.168.2.102
2006-01-12 06:39:57.8983 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x50efc34)
2006-01-12 06:39:57.8994 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:76:a8
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-12 06:39:57.9003 hello from existing client: 00:04:20:05:76:a8 on ipport: 192.168.2.102:43481
2006-01-12 06:39:57.9120 Slimproto accepted connection from: 192.168.2.101
2006-01-12 06:39:57.9359 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x1d47e90)
2006-01-12 06:39:57.9379 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:10:16
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 07ff
2006-01-12 06:39:57.9392 hello from existing client: 00:04:20:05:10:16 on ipport: 192.168.2.101:33334
2006-01-12 06:39:57.9707 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x1d47e90)
2006-01-12 06:39:57.9718 00:04:20:05:10:16 Squeezebox stream status:
	fullness:        0 (0%)
	bytes_received   0
2006-01-12 06:40:01.1926 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:40:01.1937 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:40:13.7714 Slimproto accepted connection from: 192.168.2.102
2006-01-12 06:40:13.8145 Got Slimproto frame, op HELO, length 10, IO::Socket::INET=GLOB(0x7003dd4)
2006-01-12 06:40:13.9840 Squeezebox says hello.
	Deviceid: 2
	revision: 40
	mac: 00:04:20:05:76:a8
	bitmapped: 32768
	reconnect: 16384
	wlan_channellist: 0000
2006-01-12 06:40:13.9851 hello from existing client: 00:04:20:05:76:a8 on ipport: 192.168.2.102:43484
2006-01-12 06:40:14.0417 Got Slimproto frame, op STAT, length 29, IO::Socket::INET=GLOB(0x7003dd4)
2006-01-12 06:40:14.0429 00:04:20:05:76:a8 Squeezebox stream status:
	fullness:        229374 (99%)
	bytes_received   608610
2006-01-12 06:40:47.3726 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:40:47.3739 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:40:53.1497 Deleting PLUGIN_RSSNEWS_SCREENSAVER from menu: SCREENSAVERS
2006-01-12 06:41:17.9610 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:41:17.9627 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:41:48.4117 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:41:48.4134 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:42:18.7599 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:42:18.7616 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:42:49.1449 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:42:49.1460 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:43:19.5278 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:43:19.5295 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:43:50.2384 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:43:50.2467 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:44:20.9747 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:44:21.0260 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:44:51.9489 Setting maxBitRate for Master Bedroom to: 0
2006-01-12 06:44:51.9507 Setting maxBitRate for Master Bedroom to: 0
Comment 10 Julius Friede 2006-01-17 07:19:33 UTC
Since downloading the 1/12 nightly build the alarm has been working properly. I hope this posting doesn�t jinx it:-)
Comment 11 Julius Friede 2006-01-18 06:41:58 UTC
A pattern is beginning to emerge. It seems that whenever a scheduled backup of my boot drive occurs, at 3:30am, this problems appears. My alarm is set for 6:00am, well after the backup is completed. I have no clue as to why these two events are related, but that is what seems to be happening. Any suggestions as to how to track if this is truly related? FWIW, the backup program is called SuperDuper! from Shirt-Pocket software (http://www.shirt-pocket.com/).

Thanks.
Comment 12 Dan Sully 2006-04-21 12:03:32 UTC
Julius - is this still happening with the latest 6.2.2 nightly builds?

We're very familiar with SuperDuper! I know the author.

If the problem is still happening, can you try disabling the backup and see if that fixes it?

That will at least give us a bit to go on.

Thanks.
Comment 13 Julius Friede 2006-04-22 14:02:29 UTC
I am using the 3/27 nightly build of v.6.2.x and the problem remains. If no backup is performed, there is no problem. After a backup, the alarm will activate,but the server starts to play, resets to the beginning of the track, starts to play, resets, etc. Sound never actually comes out of the player. I guess it is some kind of buffering problem. Power cycling the player restore all to normal.

I tried the 4/7 and 4/10 nightlies and the problem was worse. It didn�t even take a backup to cause the above mentioned behavior. It always happened. I then reverted to the 3/27 build because a power cycle, while a bit inconvenient, I only had to do it every few days after a backup. I have not tried any builds since then. I�ll try today�s and see if there is any improvement.
Comment 14 Julius Friede 2006-04-22 19:23:57 UTC
I tried the 4/22 build and the problem still persists. In some ways it was worse. Until I power cycled my player, I couldn�t even connect to the server via my browser. If there is somrthing you would like me to try, just let me know.
Comment 15 Julius Friede 2006-04-28 12:55:49 UTC
I installed the just released v6.2.2 and the problem still exists. What I did find out was that after the backup and the alarm activating not fully playing was that the server interface took a long time to open. Once opened, I could see that the song would start to play and then reset, start to play and reset, etc. Stopping and starting the player from the interface transport controls also cured the problem, so a power cycle of the player is not the only cure.

I will perform any tests you request to help resolve this, but you need to ask me what you would like to see. I am using the Fishbone skin if that makes any difference.

Thanks.
Julius
Comment 16 Julius Friede 2006-05-17 13:16:26 UTC
I am up to using the 5/16/06 release of v6.3.x and the problem is the same. Just curious, but should I even bother thinking that this issue might be addressed at some time? FWIW, this problem only effects my Squeezeboxes (3 of them). A Squeezebox 2 works perfectly.
Comment 17 Blackketter Dean 2006-06-06 22:19:26 UTC
Hey Julius.  Dave Nanian (of Super Duper fame) and I are stumped on this.  I suspect that it has something to do with your network (are you doing a network backup?) and the Squeezebox getting confused.  We don't have any other reports of this and can't seem to reproduce it.  Do you have any third-party SlimServer plugins installed?  What's different between your Squeezebox and Squeezebox2 installations?

Trying to think of something that could cause this here....
Comment 18 Blackketter Dean 2006-06-12 08:29:49 UTC
Pushing off to 6.5 pending more information from Julius.
Comment 19 Dan Sully 2006-07-23 18:11:27 UTC
Julius?
Comment 20 Julius Friede 2006-07-23 19:31:27 UTC
Yes, Dan? Nothing has changed. I still must power cycle my Squeezebox after a volume sync with Super Duper. My single SB2 doesn't suffer this problem, but my 3 SB1's do. I am currently using the official 6.3.1 release of SS. I am still willing to try and troubleshoot this, but I never seem to get a response for a while now, (although I did initially) when I ask about it. Thanks for asking.
Comment 21 Blackketter Dean 2006-08-16 15:09:55 UTC
Julius, we really can't reproduce this here.  My best suggestion would be to try the 6.5 version, but since it's player model specific I can only guess that something strange is happening to your network that's triggering a bug in the squeezebox1 firmware.
Comment 22 Julius Friede 2006-08-17 08:22:26 UTC
Thanks for all your efforts guys. I bit the bullet and reinstalled my system from scratch and SlimServer v6.3.1 works as expected now with no glitches. I don�t know what it was as there were no other symptoms, but there must have been something floating around in my system. Thanks again.

Julius
Comment 23 James Richardson 2008-12-15 13:05:16 UTC
This bug appears to have been fixed in the latest release!

If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.

Make sure to include the version number of the software you are seeing the error with.