MySqueezebox.com & Squeezebox Server

[grosspointblank]

Hi,

I've been an avid squeezebox user for many years but have recently been experiencing a problem with my setup - the playback will freeze intermittently for a period, sometimes many minutes, then restart without warning. I have 4 players (2 Booms, one classic and one receiver), and one controller. Server is a tiny Ubuntu box running v7.7.2 - r33893. Music is stored on a nearby Maxtor NAS drive. So I'm very prepared for it to be a problem on my network somewhere, just need help on diagnosis...

I managed to grab a chunk of data from server.log during a recent freeze. Does this point to a root cause, or are there other logging settings I should enable?

(notice the long gap between the highlighted lines - this was about 2:30 into a playing track)

[12-07-09 20:04:43.6740] Slim::Networking::Async::disconnect (236) Close Slim::Networking::Async:ocket::HTTP=GLOB(0xcdc3554) => 44

[12-07-09 20:05:31.1158] Slim:layer:layer::trackJiffiesEpoch (981) 00:04:20:06:38:fb adjust jiffies epoch +0.001s

[12-07-09 20:07:55.5945] Slim:layer:queezebox2::startAt (1068) 00:04:20:1f:60:18 startAt: 1071916747

[12-07-09 20:07:55.6013] Slim:layer:queezebox2::startAt (1068) 00:04:20:06:38:fb startAt: 99739065

[12-07-09 20:07:55.6814] Slim:layer:treamingController::_CheckSync (498) 00:04:20:1f:60:18 bailing as no playPoint

[12-07-09 20:07:57.4804] Slim:layer:treamingController::_CheckSync (526) playPoints: 00:04:20:1f:60:18: 1341860876.166, 00:04:20:06:38:fb:    +3

[12-07-09 20:07:58.4875] Slim:layer:treamingController::_CheckSync (526) playPoints: 00:04:20:1f:60:18: 1341860876.166, 00:04:20:06:38:fb:    +3

[garymc]

these things look pretty normal (checking sync, etc.). Do you have the server log setting (in LMS>SETTINGS>ADVANCED>logging set to "debug"

[grosspointblank]

Server logging as follows:

(server) - General Server Information : debug

(server.memory) - Server Memory Usage (Advanced) : off

(server.plugins) - Plugin Module Loading : debug

(server.scheduler) - Internal Scheduler Logging : error

(server.select) - Internal Select Loop Logging (Advanced) : error

(server.timers) - Internal Timer Information : error

(server.update) - Information about automatic software update downloads : error

Should I switch any others to debug ?

[garymc]

those settings should work to capture enough info

[grosspointblank]

OK. Had a couple more freezes. This is the debug captured during one of the brief pauses in playback. I'm forming a theory of my own, which is that the furthest player is the culprit, having a wifi signal of only 19% compared with 60%+ for the other players. This to my untrained eye looks like the furthest player (:fb) losing its place, and the other players halting until it rejoins and catches up. 

Player info:

Kitchen

Player Model: Squeezebox Boom

Firmware: 57

Player IP Address: 192.168.0.7

Player MAC Address: 00:04:20:1f:60:18

Wireless Signal Strength: 60%

 

Lounge

Player Model: Squeezebox Boom

Firmware: 57

Player IP Address: 192.168.0.8

Player MAC Address: 00:04:20:1f:53:d6

Wireless Signal Strength: 83%

Playroom

Player Model: Squeezebox Classic

Firmware: 137

Player IP Address: 192.168.0.17

Player MAC Address: 00:04:20:06:38:fb

Wireless Signal Strength: 19%

 

Questions:

1. Does that sound right, and does the debug info support the theory?

2. I'm figuring out how to either boost the signal or get cabled ethernet to the offending player, but is there anything else I can do to make the playback more tolerant?

[12-07-14 21:23:18.5977] Slim::Player::StreamingController::_CheckSync (526) playPoints: 00:04:20:1f:60:18: 1342297343.001, 00:04:20:1f:53:d6:    +0, 00:04:20:06:38:fb:    +0
[12-07-14 21:23:19.5935] Slim::Player::StreamingController::_CheckSync (526) playPoints: 00:04:20:1f:60:18: 1342297343.001, 00:04:20:1f:53:d6:    +0, 00:04:20:06:38:fb:    +0
[12-07-14 21:23:20.5934] Slim::Player::StreamingController::_CheckSync (526) playPoints: 00:04:20:1f:60:18: 1342297343.001, 00:04:20:1f:53:d6:    +0, 00:04:20:06:38:fb:    +0
[12-07-14 21:23:21.5929] Slim::Player::StreamingController::_CheckSync (510) 00:04:20:06:38:fb bailing as playPoint too old: 3.69726800918579s
[12-07-14 21:23:22.5929] Slim::Player::StreamingController::_CheckSync (510) 00:04:20:06:38:fb bailing as playPoint too old: 4.69724822044373s
[12-07-14 21:23:23.5989] Slim::Player::StreamingController::_CheckSync (510) 00:04:20:06:38:fb bailing as playPoint too old: 5.70296120643616s
[12-07-14 21:23:24.5930] Slim::Player::StreamingController::_CheckSync (510) 00:04:20:06:38:fb bailing as playPoint too old: 6.69728016853333s
[12-07-14 21:23:25.5929] Slim::Player::StreamingController::_CheckSync (510) 00:04:20:06:38:fb bailing as playPoint too old: 7.69724702835083s
[12-07-14 21:23:26.6086] Slim::Player::StreamingController::_CheckSync (510) 00:04:20:06:38:fb bailing as playPoint too old: 8.71294713020325s
[12-07-14 21:23:27.5960] Slim::Player::StreamingController::_CheckSync (510) 00:04:20:06:38:fb bailing as playPoint too old: 9.7002170085907s
[12-07-14 21:23:27.9009] Slim::Player::StreamingController::playerInactive (2166) 00:04:20:1f:60:18 sync group now has: 00:04:20:1f:60:18,00:04:20:1f:53:d6,00:04:20:06:38:fb
[12-07-14 21:23:27.9057] Slim::Player::StreamingController::playerInactive (2167) 00:04:20:1f:60:18 active players are: 00:04:20:1f:60:18,00:04:20:1f:53:d6
[12-07-14 21:23:27.9256] Plugins::SyncOptions::Plugin::getSyncPeers (322) peers for 00:04:20:06:38:fb are 00:04:20:1f:60:18, 00:04:20:1f:53:d6
[12-07-14 21:23:27.9478] Slim::Player::StreamingController::playerActive (2107) 00:04:20:1f:60:18 sync group now has: 00:04:20:1f:60:18,00:04:20:1f:53:d6,00:04:20:06:38:fb
[12-07-14 21:23:27.9526] Slim::Player::StreamingController::playerActive (2108) 00:04:20:1f:60:18 active players are: 00:04:20:1f:60:18,00:04:20:1f:53:d6,00:04:20:06:38:fb
[12-07-14 21:23:27.9574] Slim::Player::StreamingController::playerActive (2112) 00:04:20:1f:60:18 restart play
[12-07-14 21:23:28.2030] Slim::Player::Player::trackJiffiesEpoch (954) 00:04:20:06:38:fb adjust jiffies epoch +1341761141.199s
[12-07-14 21:23:28.2124] Plugins::SyncOptions::Plugin::newSong (371) newSong callback running
[12-07-14 21:23:28.2281] Plugins::SyncOptions::Plugin::getSongId (654) 00:04:20:1f:60:18: currently playing "Writing To Reach You	The Man Who [Explicit]	Travis	3:41	/mnt/maxtor01-public/Our Music/Travis/The Man Who [Explicit]/01 - Writing To Reach You.mp3	FILE"
[12-07-14 21:23:28.2329] Plugins::SyncOptions::Plugin::newSong (377) newSong: 00:04:20:1f:60:18/Kitchen playing Writing To Reach You	The Man Who [Explicit]	Travis	3:41	/mnt/maxtor01-public/Our Music/Travis/The Man Who [Explicit]/01 - Writing To Reach You.mp3	FILE
[12-07-14 21:23:28.2385] Plugins::SyncOptions::Plugin::newSong (381) new song on 00:04:20:1f:60:18, updating lastSongChange to now
[12-07-14 21:23:28.3205] Slim::Player::Player::trackJiffiesEpoch (954) 00:04:20:06:38:fb adjust jiffies epoch -0.092s
[12-07-14 21:23:28.3263] Slim::Player::Player::trackJiffiesEpoch (954) 00:04:20:06:38:fb adjust jiffies epoch -0.008s
[12-07-14 21:23:28.3399] Slim::Player::Player::trackJiffiesEpoch (954) 00:04:20:06:38:fb adjust jiffies epoch -0.045s
[12-07-14 21:23:28.3528] Plugins::SyncOptions::Plugin::newSong (371) newSong callback running
[12-07-14 21:23:28.3685] Plugins::SyncOptions::Plugin::getSongId (654) 00:04:20:1f:60:18: currently playing "Writing To Reach You	The Man Who [Explicit]	Travis	3:41	/mnt/maxtor01-public/Our Music/Travis/The Man Who [Explicit]/01 - Writing To Reach You.mp3	FILE"
[12-07-14 21:23:28.3732] Plugins::SyncOptions::Plugin::newSong (377) newSong: 00:04:20:1f:60:18/Kitchen playing Writing To Reach You	The Man Who [Explicit]	Travis	3:41	/mnt/maxtor01-public/Our Music/Travis/The Man Who [Explicit]/01 - Writing To Reach You.mp3	FILE
[12-07-14 21:23:28.3788] Plugins::SyncOptions::Plugin::newSong (381) new song on 00:04:20:1f:60:18, updating lastSongChange to now
[12-07-14 21:23:28.4679] Plugins::SyncOptions::Plugin::getSyncPeers (322) peers for 00:04:20:06:38:fb are 00:04:20:1f:60:18, 00:04:20:1f:53:d6
[12-07-14 21:23:28.7715] Slim::Player::Player::trackJiffiesEpoch (954) 00:04:20:06:38:fb adjust jiffies epoch -0.097s
[12-07-14 21:23:29.0704] Slim::Player::Player::trackJiffiesEpoch (954) 00:04:20:06:38:fb adjust jiffies epoch -0.034s
[12-07-14 21:23:32.5873] Slim::Player::Squeezebox2::startAt (1068) 00:04:20:1f:60:18 startAt: 1508456270
[12-07-14 21:23:32.5943] Slim::Player::Squeezebox2::startAt (1068) 00:04:20:1f:53:d6 startAt: 1508465832
[12-07-14 21:23:32.6006] Slim::Player::Squeezebox2::startAt (1068) 00:04:20:06:38:fb startAt: 536272160
[12-07-14 21:23:32.6521] Plugins::SyncOptions::Plugin::newSong (371) newSong callback running
[12-07-14 21:23:32.6698] Plugins::SyncOptions::Plugin::getSongId (654) 00:04:20:1f:60:18: currently playing "Writing To Reach You	The Man Who [Explicit]	Travis	3:41	/mnt/maxtor01-public/Our Music/Travis/The Man Who [Explicit]/01 - Writing To Reach You.mp3	FILE"
[12-07-14 21:23:32.6757] Plugins::SyncOptions::Plugin::newSong (377) newSong: 00:04:20:1f:60:18/Kitchen playing Writing To Reach You	The Man Who [Explicit]	Travis	3:41	/mnt/maxtor01-public/Our Music/Travis/The Man Who [Explicit]/01 - Writing To Reach You.mp3	FILE
[12-07-14 21:23:32.6815] Plugins::SyncOptions::Plugin::newSong (381) new song on 00:04:20:1f:60:18, updating lastSongChange to now
[12-07-14 21:23:32.7074] Slim::Player::StreamingController::_CheckSync (498) 00:04:20:1f:60:18 bailing as no playPoint
[12-07-14 21:23:33.9193] Slim::Player::Player::trackJiffiesEpoch (954) 00:04:20:06:38:fb adjust jiffies epoch -0.004s
[12-07-14 21:23:34.0762] Slim::Player::StreamingController::_CheckSync (526) playPoints: 00:04:20:1f:60:18: 1342297413.176, 00:04:20:1f:53:d6:    -3, 00:04:20:06:38:fb:    +1
[12-07-14 21:23:35.5993] Slim::Player::StreamingController::_CheckSync (526) playPoints: 00:04:20:1f:60:18: 1342297413.176, 00:04:20:1f:53:d6:    -3, 00:04:20:06:38:fb:    +1
[12-07-14 21:23:36.6095] Slim::Player::StreamingController::_CheckSync (526) playPoints: 00:04:20:1f:60:18: 1342297413.176, 00:04:20:1f:53:d6:    -3, 00:04:20:06:38:fb:    +1
[12-07-14 21:23:37.5980] Slim::Player::StreamingController::_CheckSync (526) playPoints: 00:04:20:1f:60:18: 1342297413.176, 00:04:20:1f:53:d6:    -3, 00:04:20:06:38:fb:    +1
[12-07-14 21:23:38.5954] Slim::Player::StreamingController::_CheckSync (526) playPoints: 00:04:20:1f:60:18: 1342297413.176, 00:04:20:1f:53:d6:    -3, 00:04:20:06:38:fb:    +1
[12-07-14 21:23:39.6029] Slim::Player::StreamingController::_CheckSync (526) playPoints: 00:04:20:1f:60:18: 1342297413.176, 00:04:20:1f:53:d6:    -3, 00:04:20:06:38:fb:    +1
[12-07-14 21:23:40.6009] Slim::Player::StreamingController::_CheckSync (526) playPoints: 00:04:20:1f:60:18: 1342297413.176, 00:04:20:1f:53:d6:    -2, 00:04:20:06:38:fb:    +1
[12-07-14 21:23:41.6004] Slim::Player::StreamingController::_CheckSync (526) playPoints: 00:04:20:1f:60:18: 1342297413.176, 00:04:20:1f:53:d6:    -3, 00:04:20:06:38:fb:    +1

[garymc]

don't have time to read your post at the moment, but anything less than about 60% wifi strength is problematic. So with 19% all bets are off ....

[squeezeit]

If all players are sync'd and one player has only 19% signal strength that could very well cause an issue.  Simple to test, just un-sync the players or remove that one player from the sync group, see if the others play fine now.

[garymc]

If you have trouble with WIFI reaching all your devices, you might consider something like ethernet over powerlines for those devices. I use this one and it took about 10 seconds to setup out of the box and works perfectly. 

http://www.amazon.com/gp/product/B007ILFFS6/ref=oh_details_o01_s00_i00

[grosspointblank]

Thanks, have stuck another powerline adapter nearby and connected the player. I'll look out to see if I still get freezes on playback. Thanks for the tips on reading the debug messages.

[garymc]

In case you don't know, be sure to resetup network connection. Pluggin in ethernet cable doesn't automatically switch to ethernet from wifi.