PDA

View Full Version : rpi3+pcp3.22+LMS causes transporter & SBradio to jump in and out of LMS



_NK_
2017-10-29, 09:47
Hello community :)

After following the pcp project for a looooong time I decided to take the next step after spotify pulling the plug and the amazing Mr. Herger coming to the rescue once again. (many "thank yous" Michael!)

First I'll start by saying I was *very* impressed by the simplicity effectiveness and performance of the rpi+pcp+lms combo. I only made a quick test with pcp as a player (usb connected speakers) and as I expected all this time one of my future projects will definitely be a pcp portable player with all the jivelite+touch screen goodies etc

So big kudos to the pcp team and many "thank yous" as well. Keep up the amazing progress guys!

Now since my current needs called for a server combo I set aside the speakers and focused on serving my transporter + radio (boom is currently offline for
the time being but will be joining the herd soon)

All _sort of_ worked as supposed to but there are some isssues:

- the connected to lms clients (transp + radio) appear to connect and disconnect every 10 secs or thereabout...no this does *not* appear to be an _exact_ period but more of a rough description of the behaviour ie client is connected......after 10 secs or so disconnects.....after 1sec connects again...after 10secs disconnects etc

- everything is wired nothing is wireless. a ping -t to the pcp shows no dropouts and all latency is 0ms as expected

- when a player is playing a radio stream there are *no* audio-dropouts during all this connecting-disconnecting..I assume because of having full buffers and because the disconnection lasts only 1 sec or so

- the observation of said disconnections came while managing the radio through orangesqueeze where one can see the radio appearing and disappearing from the list of available players.

-this can not be an orangesqueeze problem since the transporter gives an audible sign whenever it loses connection to server (the digital outputs/inputs make a distinct clicking sound upon disconnection/reconnection)

-like I mentioned all is wired and I also tried connecting the rpi to a different ethernet port using a different cable


So these are my strange findings so far and I hope someone can chime in with some suggestions cause I'm out of ideas.


Nikos

_NK_
2017-11-01, 01:46
*bump*

anyone got any suggestions? lms logs show nothing.

How do I configure debugging logs in lms and whre do I check relevant logs in PCP?

Any help is welcome and *very* appreciated

Thanks

Nikos

epoch1970
2017-11-01, 03:21
Two LMS servers on the network at the same time??
(especially bad if you've cloned the second from the first)

Mnyb
2017-11-01, 06:03
Two LMS servers on the network at the same time??
(especially bad if you've cloned the second from the first)

multiple servers works fine . Until as you say you copy server.prefs and don't remove the line with the server uuid ....

Ohterwise this could be a network error

bpa
2017-11-01, 06:25
From the descrption I don't think LMS actually disconnects (does "signal" change color on radio display ? does display go blank on Transporter ?) - it "sounds" like the audio stream is stopped briefly.

Are the players synced ? and/or is the audio stream being transcoded/resampled ?

_NK_
2017-11-02, 02:56
Three veterans to the rescue ;) Thanks epoch1970 Mnyb bpa for jumping in!

I'm afraid troubleshooting this one will be a b*tch..

-No double lms servers here. Only one and that's the 7.9.1 that comes with PCP. Prior to spotify pulling the plug all my hardware squeezeboxes were connected only to mysqueezebox.com.

-nothing is synced (this would be next on the list provided that this strange issue is sorted out hopefully)


/*edit

- audio stream is not transcoded resampled..all is LMS default settings

/*edit


-bpa I have not checked the lcd screen of the SBradio for any relevant icons (my current setup is all wired, not sure if anything is to change to "red" but this is the first time I'm using said Radio over wire. I recall in my previous setup when SBR was wireless that upon losing wireless -or mySB.com connection can't recall- the wifi icon became red indeed)

-the Transporter when connected to mysb.com or a local lms (has installed lms in my previous house) behaves normally i.e. clicks it's optical ins/outs each time connection to server mysb or lms is lost and again each time it is restored. When I hit "off" it stays dark and noiseless till the next time I call it's services. Now with the Transporter connected to pcp's lms the behaviour is like: connects ok...plays whatever radio stream I ask normally..I stop it.."power it off via orangesqueeze or remote control"..wait a min...hear clicking sound (meaning lost server connection...wait a couple of secs...hear clicking sounds again meaning server connection restored...and the loop goes on until I decide it's time to post to the forum and ask for assistance lol

-all this I repeat can be visually verified on orangesqueeze where one can see the players Radio and Transporter appearing/disappearing/reappearing from the available players list.

-*strangely* player "picoreplayer" appears to never exhibit such behaviour (at least from orangesqueeze's pov). Is is actually rather frustrating having the KitchenRadio selected as active player in orangesq and trying to hit "pause" or whatever only to find that half a second ago KitchenRadio fell off the list causing the picoreplayer to become the active player and thus having my "pause" or whatever getting sent to picoreplayer instead.


Looking forward to your feedback guys


Nikos

___Dumb question just came to mind...should I go to mysqb.com and delete my players maybe? Said Transporter and said Radio were "registered" all these years while the newcomer picoreplayer that's not behaving silly has never been connected to mysbx.com______

Mnyb
2017-11-02, 03:15
No keep them registred , but make sure it's the same account for all players .

And also put in your mysqueezebox login in the LMS settings, it's a special tab in settings for that so that your LMS can see your mysb.com account . That way switching players back and forth goes smoothly (you can see from within LMS if a player is at mysb.com ) and the app and radio menu in LMS will work properly.
And actually if you have your LMS account set in LMS you will probably find your picore player registred at mysb.com too .

I really have no clue but....

The "picore player" is on the same PI as LMS and they don't loose conection ?, could that tell us anything ? regarding networking .

Yes radio's wifi icon turns red when conection is lost .

Further youre sure that the players are connected by ethernet ? you don't just have to put in the cables you must also redo the network setup in each player .

bpa
2017-11-02, 03:26
the Transporter when connected to mysb.com or a local lms (has installed lms in my previous house) behaves normally i.e. clicks it's optical ins/outs each time connection to server mysb or lms is lost and again each time it is restored.

The screen display is driven by LMS. so if LMS connection is broken screen will go blank. I think the audio click is when audio stream is empty not when LMS connection is gone. As player have a buffer - normally if playing and connection to LMS is broken - audio will continue unitl buffer is empty but display will change.

To be sure what is happening enable logging - network.protocol.slimproto to INFO

Mnyb
2017-11-02, 03:41
Have you checked your power on resume settings for each player ?

And also I *think* there is a setting in the audio settings for the digital out should behave if the playback is stopped , just to adopt to varius AV recievers and DAC's that auto switch depending on the state on the spdiff output .

Sorry , that I have no Touch or SB3 connected anymore they exposed this setting and i think the transporter does to, I forgot the name of this setting :/
This could affect "clicking" and input switch of in associated equipment ...

epoch1970
2017-11-02, 03:43
Unfortunately old is not synonymous with experienced. I've never run LMS off pCP...

I think it can be an issue with the Pi's hardware, with networking (on the Pi or on the switch/router), or LMS.

Pi hardware: what is connected to the Pi over USB? It is a rather frequent case that users connect too many devices to the USB ports, and some get disconnected by the platform. AFAIK max current draw is 1A over the 4 ports (e.g. max 1A with 1 port, max 500mA each for 2 ports etc.) As you know, ethernet is connected via USB so an USB reset might affect your connection. The stock PSU for Pi 3 can output 2.5A over 5V sustained. If your PSU is weak, like 1A, it is possible that all the current goes to the Pi itself and not enough remains for the USB ports.

It *think* "dmesg" could show something upon disconnects. Otherwise adding bootcode "syslog" to the line in cmdline.txt in pCP will allow /var/log/messages to be created, and there you should get a regular system log.

Networking: are you using DHCP? If not I would. In case there is a typo in networking config you can get disconnects/no connection at all. Make sure the IP used by pCP is indeed unique to the network, an IP conflict would create transient issues like the one you're seeing.
Also if you're using one of those fancy "green ethernet" network devices, try and see if disabling power management on the port used by Pi in the switch/router changes anything.

LMS: could LMS be caught in a fail/restart loop? I would open a session on pCP, check "ps" regularly and see if the main LMS process ages or on the contrary, keeps changing PID which would indicate a restart.

I don't think mySB.com would have much to do with this. If you can live without Internet for a few minutes, you could try pulling the WAN cable from the router and see if players still reset. I don't see why that would change anything but when everything's lost...

_NK_
2017-11-03, 01:58
No keep them registred , but make sure it's the same account for all players .

checked. but what do you mean "same account for all players"? Just one lms account set up in the respective lms-mysqueezebox integration tab. Is there more elsewhere?

And also put in your mysqueezebox login in the LMS settings, it's a special tab in settings for that so that your LMS can see your mysb.com account . That way switching players back and forth goes smoothly (you can see from within LMS if a player is at mysb.com ) and the app and radio menu in LMS will work properly.
And actually if you have your LMS account set in LMS you will probably find your picore player registred at mysb.com too .

checked. indeed picoreplayer is visible

I really have no clue but....

The "picore player" is on the same PI as LMS and they don't loose conection ?, could that tell us anything ? regarding networking .

that would be a hint but all network testing so far shows no issues

Yes radio's wifi icon turns red when conection is lost .

Further youre sure that the players are connected by ethernet ? you don't just have to put in the cables you must also redo the network setup in each player

double checked everything, no double IPs, all static, simple clean class c 192.168.0.x , all wired music actually plays fine spotify works. If there was no transporter clicking and no orangesqueeze to show me the players bouncing in and out I doubt I would know there was an problem .

.


pulling my hair..

bpa
2017-11-03, 02:10
pulling my hair..

Enable LMS slimproto logging which will confirm if LMS is indeed disconnecting - anything else is just speculation.

_NK_
2017-11-03, 02:15
Have you checked your power on resume settings for each player ?

I have that "stays off after power on"

And also I *think* there is a setting in the audio settings for the digital out should behave if the playback is stopped , just to adopt to varius AV recievers and DAC's that auto switch depending on the state on the spdiff output .

Sorry , that I have no Touch or SB3 connected anymore they exposed this setting and i think the transporter does to, I forgot the name of this setting :/
This could affect "clicking" and input switch of in associated equipment ...

True it's the option to have the digital outputs always on or to have them off when "powered off" (by memory - not infront the TP now) which is what I have setup..but this is not it, since when I choose to have the TP connect to mysqb (which I did revert to until this issue is resolved) the "on-off" clicking stops



..I know..a headscratcher...

_NK_
2017-11-03, 02:18
@bpa

I just posted an interesting slimproto log but I dont know where it ended up.. let me repost

_NK_
2017-11-03, 02:23
-apparently I missed the "he text that you have entered is too long (19107 characters). Please shorten it to 10000 characters long." upon hitting submit.

192.168.0.230 it the Radio and 192.168.0.10 is the PCPplayer+LMSserver

-11-03 10:38:15.7715] Slim::Networking::Slimproto::slimproto_accept (191) Accepted connection from: [192.168.0.230:34761]
[17-11-03 10:38:15.7724] Slim::Networking::Slimproto::slimproto_accept (194) Setting timer in 5 seconds to close bogus connection
[17-11-03 10:38:15.7932] Slim::Networking::Slimproto::_hello_handler (926) Killing bogus player timer.
[17-11-03 10:38:15.7945] Slim::Networking::Slimproto::_hello_handler (968) Squeezebox says hello: Deviceid: 9 revision: 0 mac: 00:04:20:2d:71:9c uuid: ab791124ae0437fbc7cc1d23f1c7aad6 bitmapped: 0 reconnect: 16384 wlan_channellist: 0000 lang: EN bytes_received: 198910623 capabilities: Model=baby,ModelName=Squeezebox Radio,Firmware=7.7.3-r16676,Rhap,alc,wma,wmap,wmal,aac,spt,ogg,flc,aif, pcm,mp3,MaxSampleRate=48000,AccuratePlayPoints,spd r,Spdirect=spotify,ImmediateCrossfade,test,Rtmp=2, Proxy=192.168.0.230:9001
[17-11-03 10:38:15.7956] Slim::Networking::Slimproto::_hello_handler (1157) Hello from existing client: 00:04:20:2d:71:9c on ipport: 192.168.0.230:34761
[17-11-03 10:38:15.7970] Slim::Player::SqueezePlay::updateCapabilities (160) unknown capability: ImmediateCrossfade=1, ignored
[17-11-03 10:38:15.7981] Slim::Player::SqueezePlay::updateCapabilities (173) formats: alc,wma,wmap,wmal,aac,spt,ogg,flc,aif,pcm,mp3,spdr ,test
[17-11-03 10:38:15.8156] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:2d:71:9c: STAT-setd: fullness=6528, output_fullness=3503224, elapsed=12421.792
[17-11-03 10:38:25.3732] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:2d:71:9c: STAT-STMt: fullness=8247, output_fullness=3513208, elapsed=12431.347
[17-11-03 10:38:26.4534] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:2d:71:9c: STAT-STMt: fullness=242, output_fullness=3494776, elapsed=12432.427
[17-11-03 10:38:26.5941] Slim::Networking::Slimproto::slimproto_accept (191) Accepted connection from: [192.168.0.10:50158]
[17-11-03 10:38:26.5950] Slim::Networking::Slimproto::slimproto_accept (194) Setting timer in 5 seconds to close bogus connection
[17-11-03 10:38:26.5961] Slim::Networking::Slimproto::client_readable (425) half-close from client: 192.168.0.10:50130
[17-11-03 10:38:26.5970] Slim::Networking::Slimproto::slimproto_close (247) connection closed
[17-11-03 10:38:26.5989] Slim::Networking::Slimproto::slimproto_close (284) setting timer to forget client in 300 secs
[17-11-03 10:38:26.6055] Slim::Networking::Slimproto::_hello_handler (926) Killing bogus player timer.
[17-11-03 10:38:26.6068] Slim::Networking::Slimproto::_hello_handler (968) Squeezebox says hello: Deviceid: 12 revision: 0 mac: b8:27:eb:4e:51:a2 uuid: 00000000000000000000000000000000 bitmapped: 0 reconnect: 16384 wlan_channellist: 0000 lang: bytes_received: 441216 capabilities: Model=squeezelite,AccuratePlayPoints=1,HasDigitalO ut=1,HasPolarityInversion=1,Firmware=v1.8.7-999,ModelName=SqueezeLite,MaxSampleRate=384000,dsf ,dff,aac,ogg,flc,aif,pcm,mp3,loc
[17-11-03 10:38:26.6080] Slim::Networking::Slimproto::_hello_handler (1157) Hello from existing client: b8:27:eb:4e:51:a2 on ipport: 192.168.0.10:50158
[17-11-03 10:38:26.6094] Slim::Player::SqueezePlay::updateCapabilities (173) formats: dsf,dff,aac,ogg,flc,aif,pcm,mp3,loc
[17-11-03 10:38:27.4832] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:2d:71:9c: STAT-STMt: fullness=0, output_fullness=3163768, elapsed=12433.457
[17-11-03 10:38:28.6111] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:2d:71:9c: STAT-STMt: fullness=0, output_fullness=3393400, elapsed=12434.583

[17-11-03 10:38:34.8437] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:2d:71:9c: STAT-STMt: fullness=1334, output_fullness=3517048, elapsed=12440.817
[17-11-03 10:38:
:
:
:
[17-11-03 10:40:15.0895] Slim::Networking::Slimproto::slimproto_accept (191) Accepted connection from: [192.168.0.10:50206]
[17-11-03 10:40:15.0904] Slim::Networking::Slimproto::slimproto_accept (194) Setting timer in 5 seconds to close bogus connection
[17-11-03 10:40:15.0915] Slim::Networking::Slimproto::client_readable (425) half-close from client: 192.168.0.10:50190
[17-11-03 10:40:15.0924] Slim::Networking::Slimproto::slimproto_close (247) connection closed
[17-11-03 10:40:15.0940] Slim::Networking::Slimproto::slimproto_close (284) setting timer to forget client in 300 secs
[17-11-03 10:40:15.1037] Slim::Networking::Slimproto::_hello_handler (926) Killing bogus player timer.
[17-11-03 10:40:15.1050] Slim::Networking::Slimproto::_hello_handler (968) Squeezebox says hello: Deviceid: 12 revision: 0 mac: b8:27:eb:4e:51:a2 uuid: 00000000000000000000000000000000 bitmapped: 0 reconnect: 16384 wlan_channellist: 0000 lang: bytes_received: 441216 capabilities: Model=squeezelite,AccuratePlayPoints=1,HasDigitalO ut=1,HasPolarityInversion=1,Firmware=v1.8.7-999,ModelName=SqueezeLite,MaxSampleRate=384000,dsf ,dff,aac,ogg,flc,aif,pcm,mp3,loc
[17-11-03 10:40:15.1061] Slim::Networking::Slimproto::_hello_handler (1157) Hello from existing client: b8:27:eb:4e:51:a2 on ipport: 192.168.0.10:50206
[17-11-03 10:40:15.1075] Slim::Player::SqueezePlay::updateCapabilities (173) formats: dsf,dff,aac,ogg,flc,aif,pcm,mp3,loc
[17-11-03 10:40:15.6314] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:2d:71:9c: STAT-STMt: fullness=8247, output_fullness=3515512, elapsed=12541.597
[17-11-03 10:40:16.7414] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:2d:71:9c: STAT-STMt: fullness=2102, output_fullness=3522424, elapsed=12542.707
[17-11-03 10:40:46.8555] Slim::Networking::Slimproto::client_readable (425) half-close from client: 192.168.0.230:34770
[17-11-03 10:40:46.8566] Slim::Networking::Slimproto::slimproto_close (247) connection closed
[17-11-03 10:40:46.8586] Slim::Networking::Slimproto::slimproto_close (284) setting timer to forget client in 300 secs

_NK_
2017-11-03, 02:33
Unfortunately old is not synonymous with experienced. I've never run LMS off pCP...

I think it can be an issue with the Pi's hardware, with networking (on the Pi or on the switch/router), or LMS.


yes but wouldn't such issue cause failures to the outcome which is the actual playing of the music?..no dropouts here..

Pi hardware: what is connected to the Pi over USB? It is a rather frequent case that users connect too many devices to the USB ports, and some get disconnected by the platform. AFAIK max current draw is 1A over the 4 ports (e.g. max 1A with 1 port, max 500mA each for 2 ports etc.) As you know, ethernet is connected via USB so an USB reset might affect your connection. The stock PSU for Pi 3 can output 2.5A over 5V sustained. If your PSU is weak, like 1A, it is possible that all the current goes to the Pi itself and not enough remains for the USB ports.

all usb ports unoccupied. rpi original 2.5a psu

It *think* "dmesg" could show something upon disconnects. Otherwise adding bootcode "syslog" to the line in cmdline.txt in pCP will allow /var/log/messages to be created, and there you should get a regular system log.


well my *nix admin days are some 20years old but I guess I will have to get back to that one of these days..

Networking: are you using DHCP? If not I would. In case there is a typo in networking config you can get disconnects/no connection at all. Make sure the IP used by pCP is indeed unique to the network, an IP conflict would create transient issues like the one you're seeing.
Also if you're using one of those fancy "green ethernet" network devices, try and see if disabling power management on the port used by Pi in the switch/router changes anything.

no green here *shame on me* all static all checked. dhcp only for the wireless phones/tablets part (outside of the static range ofcourse)

LMS: could LMS be caught in a fail/restart loop? I would open a session on pCP, check "ps" regularly and see if the main LMS process ages or on the contrary, keeps changing PID which would indicate a restart.

will do thanks epoch1970 sounds a good point

I don't think mySB.com would have much to do with this. If you can live without Internet for a few minutes, you could try pulling the WAN cable from the router and see if players still reset. I don't see why that would change anything but when everything's lost...

indeed another wise simple but useful tip thanks :)




cheers
Nikos

_NK_
2017-11-03, 02:37
it striked odd to me but..isn't lms supposed to be gapless...played two live albums through spotify/spotty puts gaps in between the songs..

bpa
2017-11-03, 02:46
-apparently I missed the "he text that you have entered is too long (19107 characters). Please shorten it to 10000 characters long." upon hitting submit.


Zip the file and attach to a post.

Edited version are never great as sometimes it is the messages that are missing that tell the story.

You said your LMS disconnect problems were with Transporter and Radio - please use these - do not show log of a Pcp player as squeezelite have too many options which can do strange things which can confuse the issue.

Mnyb
2017-11-03, 03:48
pulling my hair..

Same account for every player if you only got one mysb.com your probably ok and actually if see every player there when you log in then you are ok :) some guys may make the mistake and register every one under a new email or somesuch and inavertely create multiple accounts .
Or get used players that really are still registred on the previus owners account . Or forgot thier login and creates yet another account..

_NK_
2017-11-03, 04:40
@bpa

log attached I appreciate your taking the time to look into it

@Mnyb

nah I've been lurking way too many years to not know these caveats by now lol

Nikos

bpa
2017-11-03, 05:20
@bpa

log attached I appreciate your taking the time to look into it

There are a few odd things but first please confirm you have not modified the log in any way such as replacing Mac addresses by "******"

_NK_
2017-11-03, 05:44
indeed replaced some to protect the innocent but then I saw there were all around in different places and did not go on with the replacing.

by strange you mean the kill bogus player from the radio that keeps restasblishing a new connection on different ports?


I don't see the Transporter doing that in the logs and upon further investigation the newer findings are:

-The Radio does bounce in & out of OrangeSqueeze as mentioned. Music plays fine, spotify ok
-Transporter does *not* appear to bounce like that when both are observed through OrangeSqueeze
-Transporter keeps clicking as in losing connection but it's really rapid (the offline/online transition) and maybe that's why the displays do not have enough time to register this state transition
-Transporter clicking happens *only* while Trasnporter is "on and stand-by" or "off".
-No clicking during playback. Music ok spotify ok

-a "ps" shows a solid process id for lms so no lms restarting it seems

-dmesg shows nothing "ovbiously odd" at least in my eyes

-an ifconfig shows strangely(?) some -not many- dropouts in the line. No overruns no errors all rest is 0. Everything is wired like I said no hubs, only switches. how can I check the exact statistics negotiations of rpi's ethernet port? dmesg showed normal behaviour 100 full duplex

- another thing is lms version. upon hitting check for lms updates in lms gui it shows a new version available. (7.9.1-1509357021-noCPAN)
My current lms version is v7.9.1, 1505480690. Trying to update lms through pcp gui does not seem to do anything, is there a specific procedure to follow?

Thanks

Nikos

bpa
2017-11-03, 06:47
indeed replaced some to protect the innocent but then I saw there were all around in different places and did not go on with the replacing.
by strange you mean the kill bogus player from the radio that keeps restasblishing a new connection on different ports?


Thanks for letting me waste time by not saying you did that in the beginning.

No "bogus" message is "Normal" but I was confused by the "***" and the associated UUID being zero.

Please give me a clean log - it is necessary to match message with MAC.

With a bit if guesswork because the Mac addresses were obsucred and I could be mixuing up two or more players. It looks like there is only player playting OK but all the other players are not seeing the replies from LMS and so keep trying to communicste with LMS.

Do you have a simple network (e.g. a single router and all device on same sub net with no VLANs) or do you have something more complicated possibly with mulitple routers/switch/VLANs/subnets etc.

_NK_
2017-11-03, 07:23
Thanks for letting me waste time by not saying you did that in the beginning.

omission on my part but I would expect this to be common practice, no?

No "bogus" message is "Normal" but I was confused by the "***" and the associated UUID being zero.

Please give me a clean log - it is necessary to match message with MAC.

plz see new attached

With a bit if guesswork because the Mac addresses were obsucred and I could be mixuing up two or more players. It looks like there is only player playting OK but all the other players are not seeing the replies from LMS and so keep trying to communicste with LMS.


only 2 players in total the Radio and the Transporter (squeezelite from pcp was stopped as suggested) and they both play fine (would this lack of music dropouts be caused by having full buffers?)



Do you have a simple network (e.g. a single router and all device on same sub net with no VLANs) or do you have something more complicated possibly with mulitple routers/switch/VLANs/subnets etc.

simple clean 1 router 1 switch no vlans no qos 24 bit network no extra subnets

trying squeezeplay as well as the new squeezelitetray app on my win7 pc connected to said pcp/lms also works flawlessly

cheers

Nikos
23952

bpa
2017-11-03, 08:40
trying squeezeplay as well as the new squeezelitetray app on my win7 pc connected to said pcp/lms also works flawlessly

Obscuring MAC addresses is not usual - it is not a great safety measure since Mac address can be spoofed very easily. But if you deciode to obscure - do it everywhere and in equally (i.e. edit using a global replace) but leave enough to faciltitate debugging (i.e leave last digits not first as they are more likely to be unique ) - the application of "***" in some places and leaving trhe same MAC address unbscured in other places was just odd and why I didn't think it was done by a user.

Rather than fragments of results - can you summarise what is / is not working.

Each player has three aspects
1. Controllable by OrangeSqueeze
2. Ability to play Music.
3. Visible on LMS Web UI.

Can you summarise the status of each player against these three.
What are you playing files or internet streams ?

_NK_
2017-11-03, 09:52
Obscuring MAC addresses is not usual - it is not a great safety measure since Mac address can be spoofed very easily. But if you deciode to obscure - do it everywhere and in equally (i.e. edit using a global replace) but leave enough to faciltitate debugging (i.e leave last digits not first as they are more likely to be unique ) - the application of "***" in some places and leaving trhe same MAC address unbscured in other places was just odd and why I didn't think it was done by a user.

I see your point and I stand corrected

Rather than fragments of results - can you summarise what is / is not working.

fragments? hm yes sure

Each player has three aspects
1. Controllable by OrangeSqueeze
2. Ability to play Music.
3. Visible on LMS Web UI.

ok one more time

1. _both_ players are perfectly controllable by OSq apart from the black-hole-window (~5sec duration) during which the Radio appears to fall off the available-players-list in the OSq gui, yet this falling-off does _not_ affect whatever radio stream or spotify stream the Radio is playing during that hiccup.

2.Like mentioned numerous times both players play perfectly

3.Both players are visible on lms gui normally with no "obvious" signs of something being wrong

Can you summarise the status of each player against these three.
What are you playing files or internet streams ?

no local files. internet streams + spotify only. flawless playback

bpa
2017-11-03, 10:36
When playing music older SB player (i.e. Transport, Boom, Receiver) has two connections
1. Slimproto
2. Music over a http

With your problem players - the slimproto connection is being closed and reopened repeatedly by the player and LMS treats the open/close as a "glitch" and doesn't reinitialise the "client" datastructure as trhe connection is remade quickly (i.e. client forget timer of 300 secs does not expire) - so this is your "black hole"


17-11-03 16:09:19.0899] Slim::Networking::Slimproto::client_readable (425) half-close from client: 192.168.0.230:49843
[17-11-03 16:09:19.0908] Slim::Networking::Slimproto::slimproto_close (247) connection closed
[17-11-03 16:09:19.0926] Slim::Networking::Slimproto::slimproto_close (284) setting timer to forget client in 300 secs
[17-11-03 16:09:23.6918] Slim::Networking::Slimproto::slimproto_accept (191) Accepted connection from: [192.168.0.230:49846]
[17-11-03 16:09:23.6927] Slim::Networking::Slimproto::slimproto_accept (194) Setting timer in 5 seconds to close bogus connection
[17-11-03 16:09:23.7045] Slim::Networking::Slimproto::_hello_handler (926) Killing bogus player timer.
[17-11-03 16:09:23.7058] Slim::Networking::Slimproto::_hello_handler (968) Squeezebox says hello: Deviceid: 9 revision: 0 mac: 00:04:20:2d:71:9c uuid: ab791124ae0437fbc7cc1d23f1c7aad6 bitmapped: 0 reconnect: 0 wlan_channellist: 0000 lang: EN bytes_received: 0 capabilities: Model=baby,ModelName=Squeezebox Radio,Firmware=7.7.3-r16676,Rhap,alc,wma,wmap,wmal,aac,spt,ogg,flc,aif, pcm,mp3,MaxSampleRate=48000,AccuratePlayPoints,spd r,Spdirect=spotify,ImmediateCrossfade,test,Rtmp=2, Proxy=192.168.0.230:9001
[17-11-03 16:09:23.7069] Slim::Networking::Slimproto::_hello_handler (1157) Hello from existing client: 00:04:20:2d:71:9c on ipport: 192.168.0.230:49846


So LMS is not disconnecting but the players seems to close the slimproto connections to LMS and then very quickly make a request to reconnect. Strangely, at the same time the http music connection does not seem to have been closed but more logging would be needed to be sure.

Have you tried Xilinx reset of the players ?

paul-
2017-11-03, 11:33
- another thing is lms version. upon hitting check for lms updates in lms gui it shows a new version available. (7.9.1-1509357021-noCPAN)
My current lms version is v7.9.1, 1505480690. Trying to update lms through pcp gui does not seem to do anything, is there a specific procedure to follow?


The update in the web page takes some time to complete, depending on your download speed, and rpi. (Single vs Multiple Core), it appears as if nothing is happening. If you want, you can open an ssh session, and then run the update manually

sudo lms-update.sh -u -r

You can see the script running that way.

_NK_
2017-11-03, 13:04
When playing music older SB player (i.e. Transport, Boom, Receiver) has two connections
1. Slimproto
2. Music over a http

With your problem players - the slimproto connection is being closed and reopened repeatedly by the player and LMS treats the open/close as a "glitch" and doesn't reinitialise the "client" datastructure as trhe connection is remade quickly (i.e. client forget timer of 300 secs does not expire) - so this is your "black hole"


17-11-03 16:09:19.0899] Slim::Networking::Slimproto::client_readable (425) half-close from client: 192.168.0.230:49843
[17-11-03 16:09:19.0908] Slim::Networking::Slimproto::slimproto_close (247) connection closed
[17-11-03 16:09:19.0926] Slim::Networking::Slimproto::slimproto_close (284) setting timer to forget client in 300 secs
[17-11-03 16:09:23.6918] Slim::Networking::Slimproto::slimproto_accept (191) Accepted connection from: [192.168.0.230:49846]
[17-11-03 16:09:23.6927] Slim::Networking::Slimproto::slimproto_accept (194) Setting timer in 5 seconds to close bogus connection
[17-11-03 16:09:23.7045] Slim::Networking::Slimproto::_hello_handler (926) Killing bogus player timer.
[17-11-03 16:09:23.7058] Slim::Networking::Slimproto::_hello_handler (968) Squeezebox says hello: Deviceid: 9 revision: 0 mac: 00:04:20:2d:71:9c uuid: ab791124ae0437fbc7cc1d23f1c7aad6 bitmapped: 0 reconnect: 0 wlan_channellist: 0000 lang: EN bytes_received: 0 capabilities: Model=baby,ModelName=Squeezebox Radio,Firmware=7.7.3-r16676,Rhap,alc,wma,wmap,wmal,aac,spt,ogg,flc,aif, pcm,mp3,MaxSampleRate=48000,AccuratePlayPoints,spd r,Spdirect=spotify,ImmediateCrossfade,test,Rtmp=2, Proxy=192.168.0.230:9001
[17-11-03 16:09:23.7069] Slim::Networking::Slimproto::_hello_handler (1157) Hello from existing client: 00:04:20:2d:71:9c on ipport: 192.168.0.230:49846


So LMS is not disconnecting but the players seems to close the slimproto connections to LMS and then very quickly make a request to reconnect. Strangely, at the same time the http music connection does not seem to have been closed but more logging would be needed to be sure.

Have you tried Xilinx reset of the players ?

ok now things make more sense...just xilinx-ed the Transporter..no change..afaik there's no xilinx reset for the Radio..went ahead and issued a factory reset..will have more time to watch Radio's behaviour tomorrow

should I up the logging level of some other protocol or slimproto is enough?

do these findings so far point more likely to a 7.9.1 bug or?

thanks for your assistance on this bpa


cheers

Nikos

_NK_
2017-11-03, 13:06
The update in the web page takes some time to complete, depending on your download speed, and rpi. (Single vs Multiple Core), it appears as if nothing is happening. If you want, you can open an ssh session, and then run the update manually

sudo lms-update.sh -u -r

You can see the script running that way.


Thank you Paul I will go ahead and do so right now

Nikos

epoch1970
2017-11-03, 13:20
do these findings so far point more likely to a 7.9.1 bug or?
I would rather think something's fishy with your network or network config in PCP. As I see it (without looking at the zip), every clients dropping connections (including squeezelite), that is weird.

I understand PCP/LMS/Squeezelite is at 192.168.0.10?
Would you shut down that machine, and then try to ping 192.168.0.10. I wonder if someone might still respond.

_NK_
2017-11-03, 13:25
Thank you Paul I will go ahead and do so right now

Nikos


failed:




tc@piCorePlayer:~$ sudo lms-update.sh -u -r


################################################## #############


This script will update the Logitech Media Server extension


usage: /usr/local/bin/lms-update.sh [-u] [-d] [-m] [-r] [-s] [-t]
-u Unattended Execution
-d Debug, Temp files not erased
-m Manual download Link Check for LMS update
-r Reload LMS after Update
-s Skip Update from GitHub
-t Test building, but do not move extension to tce directory
--mm <version> Force the version you want to update. (eg 7.9.1)


Unattended Operation Enabled


Automatic Reload Enabled
################################################## #############


Press Enter to continue, or Ctrl-c to exit and change options
Updateing Script from Github...
Connecting to raw.githubusercontent.com (151.101.16.133:443)
lms-update.sh 100% |*******************************| 13190 0:00:00 ETA
Relaunching Script in 3 seconds
Updateing Slimserver customizations from Github...
Connecting to raw.githubusercontent.com (151.101.16.133:443)
custom-strings.txt 100% |*******************************| 1180 0:00:00 ETA
Connecting to raw.githubusercontent.com (151.101.112.133:443)
picore-update.html 100% |*******************************| 1240 0:00:00 ETA
Connecting to raw.githubusercontent.com (151.101.16.133:443)
Custom.pm 100% |*******************************| 2732 0:00:00 ETA
Connecting to raw.githubusercontent.com (151.101.16.133:443)
slimserver 100% |*******************************| 3764 0:00:00 ETA


No update link found. THis either means that there is no update, or you do not have automatic update
checks and automatic downloads enabled in the LMS settings.


If you would like to manually check for updates using a static update check, please relaunch this script
using the -m command line switch


DONE





then used -m switch :


tc@piCorePlayer:~$ sudo lms-update.sh -u -m -r

################################################## #############


This script will update the Logitech Media Server extension


usage: /usr/local/bin/lms-update.sh [-u] [-d] [-m] [-r] [-s] [-t]
-u Unattended Execution
-d Debug, Temp files not erased
-m Manual download Link Check for LMS update
-r Reload LMS after Update
-s Skip Update from GitHub
-t Test building, but do not move extension to tce directory
--mm <version> Force the version you want to update. (eg 7.9.1)


Unattended Operation Enabled
Manual Download Link Check Enabled
Automatic Reload Enabled
################################################## #############


Press Enter to continue, or Ctrl-c to exit and change options
Updateing Script from Github...
Connecting to raw.githubusercontent.com (151.101.112.133:443)
lms-update.sh 100% |*******************************| 13190 0:00:00 ETA
Relaunching Script in 3 seconds
Updateing Slimserver customizations from Github...
Connecting to raw.githubusercontent.com (151.101.16.133:443)
custom-strings.txt 100% |*******************************| 1180 0:00:00 ETA
Connecting to raw.githubusercontent.com (151.101.16.133:443)
picore-update.html 100% |*******************************| 1240 0:00:00 ETA
Connecting to raw.githubusercontent.com (151.101.16.133:443)
Custom.pm 100% |*******************************| 2732 0:00:00 ETA
Connecting to raw.githubusercontent.com (151.101.112.133:443)
slimserver 100% |*******************************| 3764 0:00:00 ETA
Performing manual check for update link, Current Version is: 7.9.1 r1505480690.
Connecting to www.mysqueezebox.com (54.246.73.168:80)
tmp.6uZzhJ 100% |*******************************| 104 0:00:00 ETA


Downloading update from http://downloads.slimdevices.com/nightly/7.9/sc/c558cb2/logitechmediaserver-7.9.1-1509357021-noCPAN.tgz
Connecting to downloads.slimdevices.com (54.192.230.245:80)
logitechmediaserver- 100% |*******************************| 18695k 0:00:00 ETA
Downloading required extension squashfs-tools.tcz


Downloading: squashfs-tools.tcz
Connecting to repo.tinycorelinux.net (89.22.99.37:80)
squashfs-tools.tcz 100% |*******************************| 104k 0:00:00 ETA
squashfs-tools.tcz: OK


Updating from /tmp/slimupdate/logitechmediaserver-7.9.1-1509357021-noCPAN.tgz


Extracting Update...tar: write error: No space left on device
sh: write error: No space left on device
File Extraction FAILED.....exiting!
tc@piCorePlayer:~$





tried a resize fs:

23956


Paul is this normal?

Nikos

_NK_
2017-11-03, 13:33
I would rather think something's fishy with your network or network config in PCP. As I see it (without looking at the zip), every clients dropping connections (including squeezelite), that is weird.

squeezelite seems quite solid.what do you see?

I understand PCP/LMS/Squeezelite is at 192.168.0.10?
Would you shut down that machine, and then try to ping 192.168.0.10. I wonder if someone might still respond.

did that just now cause you had me alarmed for a min but now with pcp down pinging .10 results in request timeout

bpa
2017-11-03, 13:45
ok now things make more sense...just xilinx-ed the Transporter..no change..afaik there's no xilinx reset for the Radio..went ahead and issued a factory reset..will have more time to watch Radio's behaviour tomorrow
Xilinx reset is a good step to take whenver odd behaviour happens. It does not harm. Even though the problem affects TRasnproter and Radio - I was think perhaps one device is messing up the netwrok for the second.


should I up the logging level of some other protocol or slimproto is enough?
Nothing immediatel springs to mind - need to think what is possible.


do these findings so far point more likely to a 7.9.1 bug or?
I don't think so. There are plenty of pcp LMS users and they don't have the problem so that would make more likely a local issue - either configuration/setup or network.

It is confusing that players seem to not "see" some LMS replies or replies from players are being dropped - yet manage to play music non stop.

Just to confirm - the other squeezeplay/suqeezelite are separate players from the pcp LMS system ?

Have you swapped switches to see if problem follow the switch ? I had a switch which became unreliable and would partially work - some packets would get through and some wouldn't.

_NK_
2017-11-03, 14:18
Xilinx reset is a good step to take whenver odd behaviour happens. It does not harm. Even though the problem affects TRasnproter and Radio - I was think perhaps one device is messing up the netwrok for the second.

true xilinx reset has cleared strange behaviour with the TP and a Boom in the past several times for me too


Nothing immediatel springs to mind - need to think what is possible.


I don't think so. There are plenty of pcp LMS users and they don't have the problem so that would make more likely a local issue - either configuration/setup or network.

yes but since LMS@pcp is "fairly" new and since -like observed- music playing is not affected then maybe something like this could have gone unnoticed


It is confusing that players seem to not "see" some LMS replies or replies from players are being dropped - yet manage to play music non stop.

Just to confirm - the other squeezeplay/suqeezelite are separate players from the pcp LMS system ?


-one squeezelite in the pcp server (stopped to ease troubleshooting as suggested)

-one squeezeplay (Ralphy's) was installed on my win7-pc just a couple of hours ago to see how it would behave with the pcp/lms server..worked perfectly but I did not do lengthy testing
-one squeezelite (Rdawson's) lovely Squeezelitetray wa installed on the same pc for the same purpose and to see what it was about. worked perfectly but with no lenthy testing also.

both win7pc software players were then "powered off and exited"



Have you swapped switches to see if problem follow the switch ? I had a switch which became unreliable and would partially work - some packets would get through and some wouldn't.

yes swapped cables and switches since I've had such failure as you described in the past as well..some ports would "semi-work" when things got a bit warmer in the summertime.


Nikos

bpa
2017-11-03, 14:50
yes but since LMS@pcp is "fairly" new and since -like observed- music playing is not affected then maybe something like this could have gone unnoticed
March 2016 cannot be considered new. It's possible that has gone unnotriced but the developers are experienced and then there are plenty are non Linux users who remark at the smallest oddity as well as experts who want to tweak it every way possible.

wireshark would be my normal next level of debugging - but it is not something that can be used remotely.

edit:

Since one of the problem devices is a Radio - it should be possible to enable some Radio logging and ssh into it to look at the log see what the Radio view of the break in the slimproto connection. From LMS point of view the slimproto TCP connection is broken from Radio

I'll post detail in the morning.

mherger
2017-11-03, 22:05
> Extracting Update...tar: write error: No space left on device
> sh: write error: No space left on device
> File Extraction FAILED.....exiting!

You need to expand your filesystem. Or figure out why you run out of
disk space?

--

Michael

bpa
2017-11-04, 02:38
Before doing any logging - sort out pCP disk space as lack of disk space can have strange effects.

To get logging on Radio or Touch

1. Enable Rlogin on Radio / Touch using Settings/Advanced/Remote Login
2. ssh as "root" into Radio . If you get an error as Radio/Touch use "old" encyrption the command needed may be somehting like ssh -oKexAlgorithms=+diffie-hellman-group1-sha1 root@192.168.1.xx
3. Just to check interface setting do a fconfig command and copy to a post.
4. To look at messages use tail -f /var/log/messages
5. On Radio enable logging (i.e. Settings/Advanced/Logging) net.socket and net.slimproto to DEBUG
6. On screen showing messages - wait for a few cycle of "HELO" which will have messagelike the following


Nov 4 09:13:00 squeezeplay: DEBUG net.socket - Networking.lua:2098 checkNetworkHealth task done (part)
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:650 disconnect
Nov 4 09:13:02 squeezeplay: INFO net.slimproto - SlimProto.lua:592 connect to 192.168.1.65 (192.168.1.65)
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=HELO
Nov 4 09:13:02 squeezeplay: INFO net.slimproto - SlimProto.lua:152 Send HELO: reconnect-bit=0 bytesReceived(H,L)=0,0
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:518 read opcode=strm #28
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=STAT
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:518 read opcode=strm #28
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=STAT
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:518 read opcode=setd #5
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=SETD
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=STAT
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:518 read opcode=setd #5
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=STAT
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:518 read opcode=aude #6
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=STAT
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:518 read opcode=audg #26
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=STAT


Copy and post the Radio log messages.

_NK_
2017-11-04, 04:37
> Extracting Update...tar: write error: No space left on device
> sh: write error: No space left on device
> File Extraction FAILED.....exiting!

You need to expand your filesystem. Or figure out why you run out of
disk space?

--

Michael


Hi Michael,

filesystem was(?) already expanded upon initial PCP setup when I installed LMS if I recall correctly.

current size status is
/dev/mmcblk0p2 28.8G 82.1M 27.6G 0% /mnt/mmcblk0p2

I would expect 27.6G free would be enough to not give a "not enough free space" error, or not?

Nikos

paul-
2017-11-04, 05:35
The tar file extracts to /tmp.

Your memory is filled up......Iíve not seen that before on a pi3. All disk space in pCP is in A RAM disk, except mmcblk0p2,

_NK_
2017-11-04, 06:10
last night as discussed I shutdown pcp via gui and then issued a ping to pcp from pc where I got Request timout as expected.

I did *not* unplug the pcp from mains...and this morning out of curiosity I isuued another ping


C:\Users\nikos>ping 192.168.0.10

Pinging 192.168.0.10 with 32 bytes of data:
Request timed out.
Request timed out.
Request timed out.
Reply from 192.168.0.110: Destination host unreachable.


Ping statistics for 192.168.0.10:
Packets: Sent = 4, Received = 1, Lost = 3 (75% loss),


C:\Users\nikos>ping 192.168.0.10


Pinging 192.168.0.10 with 32 bytes of data:
Request timed out.
Request timed out.
Request timed out.
Request timed out.


Ping statistics for 192.168.0.10:
Packets: Sent = 4, Received = 0, Lost = 4 (100% loss),


C:\Users\nikos>ping 192.168.0.10


Pinging 192.168.0.10 with 32 bytes of data:
Reply from 192.168.0.110: Destination host unreachable.
Request timed out.
Reply from 192.168.0.110: Destination host unreachable.
Request timed out.


Ping statistics for 192.168.0.10:
Packets: Sent = 4, Received = 2, Lost = 2 (50% loss),


C:\Users\nikos>ping 192.168.0.10


Pinging 192.168.0.10 with 32 bytes of data:
Reply from 192.168.0.110: Destination host unreachable.
Request timed out.
Request timed out.
Request timed out.


Ping statistics for 192.168.0.10:
Packets: Sent = 4, Received = 1, Lost = 3 (75% loss),




x.110 is my pc and host unreachable would be perfectly normal as long as this was 100% consistent...without the intermittent Request timouts. after all this ping was issued 13 hours later than the first one.

A new Advanced Ip Scanner run shows two deads:

192.168.0.10 Raspberry Pi Foundation B8:27:EB:4E:51:A2

*and*

192.168.0.231 Raspberry Pi Foundation B8:27:EB:4E:51:A2


All these days with the pcp online, an Advanced Ip Scanner run would never show the x.231 and would only show the x.10 as alive-and-kicking...

??????

Background info:

My first attempt at setting up pcp was interrupted since after the image being burnt to the sd I could not get an ip address through dhcp (was to be expected since the router at the office has a dodgy semi-working dhpc implementation and I had not hdmi cable at hand to use console.


So when I got home that night I connected the pcp to my monitor..run setup..issued the x.10 static address verified that wifi was off..and the rest is history.


Could there be a x.231 address left behind "somewhere" in the pcp config files from when the pcp tried to get a first ip during it's very first dhcp attempt? If so where would such address be stuck?


Also upon some digging in pcp files I paste below a message which may or may not be of use:


tc@piCorePlayer:/var/log$ cat pcp_boot.logStarting piCorePlayer setup...
Loading pcp-functions...and pCP configuration file.sh: 3: unknown operand
Done.



Any advice is highly appreciated.

I could always wipe the sd and burn pcp from scratch but I think it's much better to understand what is going on before I evaporize the body.

Nikos

ps:epoch1970 kudos ;)

_NK_
2017-11-04, 06:14
The tar file extracts to /tmp.

Your memory is filled up......Iíve not seen that before on a pi3. All disk space in pCP is in A RAM disk, except mmcblk0p2,


Hi Paul,

I wish I could have something to say but this is way beyond my infinite wisdom. Please let me know if there is any info you may need to help you identify whether it's gremlins under the hood or a simple case of daemonic possession

cheers

Nikos

_NK_
2017-11-04, 06:21
Before doing any logging - sort out pCP disk space as lack of disk space can have strange effects.

To get logging on Radio or Touch

1. Enable Rlogin on Radio / Touch using Settings/Advanced/Remote Login
2. ssh as "root" into Radio . If you get an error as Radio/Touch use "old" encyrption the command needed may be somehting like ssh -oKexAlgorithms=+diffie-hellman-group1-sha1 root@192.168.1.xx
3. Just to check interface setting do a fconfig command and copy to a post.
4. To look at messages use tail -f /var/log/messages
5. On Radio enable logging (i.e. Settings/Advanced/Logging) net.socket and net.slimproto to DEBUG
6. On screen showing messages - wait for a few cycle of "HELO" which will have messagelike the following


Nov 4 09:13:00 squeezeplay: DEBUG net.socket - Networking.lua:2098 checkNetworkHealth task done (part)
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:650 disconnect
Nov 4 09:13:02 squeezeplay: INFO net.slimproto - SlimProto.lua:592 connect to 192.168.1.65 (192.168.1.65)
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=HELO
Nov 4 09:13:02 squeezeplay: INFO net.slimproto - SlimProto.lua:152 Send HELO: reconnect-bit=0 bytesReceived(H,L)=0,0
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:518 read opcode=strm #28
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=STAT
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:518 read opcode=strm #28
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=STAT
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:518 read opcode=setd #5
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=SETD
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=STAT
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:518 read opcode=setd #5
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=STAT
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:518 read opcode=aude #6
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=STAT
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:518 read opcode=audg #26
Nov 4 09:13:02 squeezeplay: DEBUG net.slimproto - SlimProto.lua:717 send opcode=STAT


Copy and post the Radio log messages.


Hi bpa,

thank you for your persistence on this. I really appreciate your assistance.

Having some new findings at hand so I will hold this as the next troubleshooting step in line after the underlying problems are sorted.

cheers

Nikos

_NK_
2017-11-04, 06:25
@paul




tc@piCorePlayer:/tmp$ free
total used free shared buffers cached
Mem: 1000308 256584 743724 11632 17552 60104
-/+ buffers/cache: 178928 821380
Swap: 241852 0 241852
tc@piCorePlayer:/tmp$

Nikos

paul-
2017-11-04, 06:36
I’m not as concerned about the unknown op message, I just found that bug over the weekend, but it should not stop anything critical. there should be more data in the boot log.

As for the memory, it could be LMS using a lot of space. Try to upgrade it right after reboot. The upgrade process only uses about 20mb.

How big is your music library? And what is the settings in LMS. Advanced Tab, Performance, Database memory config?

Edit: I didn’t see the free output till now. There is plenty of memory now, is it still failing? What is the full output of the upgrade script?

_NK_
2017-11-04, 09:22
@paul

lms upgrade right after the reboot worked flawlessly as you suggested. *thumbs up*

here is the output:


sudo lms-update.sh -u -m -r

################################################## #############


This script will update the Logitech Media Server extension


usage: /usr/local/bin/lms-update.sh [-u] [-d] [-m] [-r] [-s] [-t]
-u Unattended Execution
-d Debug, Temp files not erased
-m Manual download Link Check for LMS update
-r Reload LMS after Update
-s Skip Update from GitHub
-t Test building, but do not move extension to tce directory
--mm <version> Force the version you want to update. (eg 7.9.1)


Unattended Operation Enabled
Manual Download Link Check Enabled
Automatic Reload Enabled
################################################## #############


Press Enter to continue, or Ctrl-c to exit and change options
Updateing Script from Github...
Connecting to raw.githubusercontent.com (151.101.16.133:443)
lms-update.sh 100% |*******************************| 13190 0:00:00 ETA
Relaunching Script in 3 seconds
Updateing Slimserver customizations from Github...
Connecting to raw.githubusercontent.com (151.101.112.133:443)
custom-strings.txt 100% |*******************************| 1180 0:00:00 ETA
Connecting to raw.githubusercontent.com (151.101.16.133:443)
picore-update.html 100% |*******************************| 1240 0:00:00 ETA
Connecting to raw.githubusercontent.com (151.101.112.133:443)
Custom.pm 100% |*******************************| 2732 0:00:00 ETA
Connecting to raw.githubusercontent.com (151.101.16.133:443)
slimserver 100% |*******************************| 3764 0:00:00 ETA
Performing manual check for update link, Current Version is: 7.9.1 r1505480690.
Connecting to www.mysqueezebox.com (54.217.146.147:80)
tmp.xQHQHx 100% |*******************************| 104 0:00:00 ETA


Downloading update from http://downloads.slimdevices.com/nightly/7.9/sc/c558cb2/logitechmediaserver-7.9.1-1509357021-noCPAN.tgz
Connecting to downloads.slimdevices.com (52.222.168.236:80)
logitechmediaserver- 100% |*******************************| 18695k 0:00:00 ETA
Loading Local Extension squashfs-tools.tcz


squashfs-tools.tcz: OK


Updating from /tmp/slimupdate/logitechmediaserver-7.9.1-1509357021-noCPAN.tgz


Extracting Update.../
Tar Extraction Complete, Building Updated Extension Filesystem


Press Enter to continue, or Ctrl-c to exit


Update in progress .../tmp/slimupdate/lms-update.sh




Done Updating Files. The files are ready to be packed into the new extension


Press Enter to continue, or Ctrl-c to exit
Creating extension, it may take a while ... especially on rpi 0/A/B/A+/B+
Parallel mksquashfs: Using 4 processors
Creating 4.0 filesystem on /tmp/slimserver.tcz, block size 131072.
[================================================== ===========\] 2353/2353 100%


Exportable Squashfs 4.0 filesystem, gzip compressed, data block size 131072
compressed data, compressed metadata, compressed fragments, no xattrs
duplicates are removed
Filesystem size 18208.94 Kbytes (17.78 Mbytes)
45.89% of uncompressed filesystem size (39683.11 Kbytes)
Inode table size 26060 bytes (25.45 Kbytes)
28.63% of uncompressed inode table size (91020 bytes)
Directory table size 26278 bytes (25.66 Kbytes)
44.00% of uncompressed directory table size (59721 bytes)
Number of duplicate files found 62
Number of inodes 2821
Number of files 2215
Number of fragments 159
Number of symbolic links 0
Number of device nodes 0
Number of fifo nodes 0
Number of socket nodes 0
Number of directories 606
Number of ids (unique uids + gids) 2
Number of uids 1
root (0)
Number of gids 1
staff (50)
Ready to Reload LMS, Press Enter to Continue
Stopping LMS
Slimserver Stopped
Waiting for File Handles to Close
Unmounting Extension
Moving new Extension to /mnt/mmcblk0p2/tce/optional


Syncing filesystems
Loading new Extension
slimserver.tcz: OK
Starting New Version of LMS
[17-11-04 18:07:18.5476] main::init (387) Starting Logitech Media Server (v7.9.1, 1509357021, Mon Oct 30 10:15:06 UTC 2017) perl 5.024000 - arm-linux-gnueabihf-thread-multi-64int
[17-11-04 18:07:18.5703] main::init (417) OS Specific init...
[17-11-04 18:07:18.5716] main::init (451) Server daemonizing...
[17-11-04 18:07:18.5814] Slim::bootstrap::theEND (439) Got to the END


Slimserver Running pid:8072




Press Enter to Cleanup and exit


Deleting the temp folders
DONE


tc@piCorePlayer:~$
tc@piCorePlayer:~$





regarding the previous pcp_boot.log (before the succesfull lms upgrade) here is the saved full output:


tc@piCorePlayer:/var/log$ cat pcp_boot.logStarting piCorePlayer setup...
Loading pcp-functions...and pCP configuration file.sh: 3: unknown operand
Done.
Checking for newconfig.cfg on mmcblk0p1...
Trying to mount /dev/mmcblk0p1.
newconfig.cfg not found on mmcblk0p1.
Setting piCore repository... Done.
Generating drop-down list... Done.
Loading configuration file... Done.
Checking wifi... Done.
Loading pcp-lms-functions... Done.
Waiting for soundcards to populate. Done (1).
Starting ALSA configuration... Done.
Checking proper card number for Alsaequal... Done.
Waiting for network. Done (1).
Starting Openssh server... Done.
Starting LMS, this can take some time... [17-11-04 11:06:45.9629] main::init (387) Starting Logitech Media Server (v7.9.1, 1505480690, Fri Sep 15 22:32:08 UTC 2017) perl 5.024000 - arm-linux-gnueabihf-thread-multi-64int
[17-11-04 11:06:45.9795] main::init (417) OS Specific init...
[17-11-04 11:06:45.9804] main::init (451) Server daemonizing...
[17-11-04 11:06:45.9913] Slim::bootstrap::theEND (439) Got to the END


Slimserver Running pid:4564
Done.
Waiting for LMS to initiate... Done (3).
Starting Squeezelite... Done.
Starting httpd web server... Done.
eth0 IP: 192.168.0.10
Finished piCorePlayer setup.
crond syncing time...
tc@piCorePlayer:/var/log$

Regarding the strange out of memory issue I will run this updated lms and report back.

Local library size is _ZERO_ as my current pcp need was to have lms to be able to have spotify not for local files.

Do you have some suggestion maybe regarding the phantom dual ip address in pcp?

Looking forward to your feedback

Nikos

_NK_
2017-11-04, 09:25
@paul

forgot..lms performance settings were the default "High"

cheers

Nikos

paul-
2017-11-04, 16:37
When you shutdown pCP from the web interface it completely shuts down and halts the OS, so there is no way for it to respond to a arp request that would show up. There is nothing in pCP that can set up more than one address. When in dhcp mode, the network address is not saved anywhere persistent, so the next reboot, the pCP device would have no idea what address it had the last boot.

I'm not sure you said.....what brand/model is your router? Looking at the address reservations on the router would be a good place to start. Are you static vs dhcp ranges separated?

_NK_
2017-11-07, 08:57
Hi Paul,

Indeed there's no explanation for the phantom ip apparently, but on the other hand I'm 1000% sure of what I saw on the Advanced Ip Scanner output..maybe a glitch (like I mentioned the phantom ip had the same mac and the same "raspberry pi foundation etc" in the description, and I surely own just 1 pi)

The router is a TP-Link WD9977 and the dhcp pool is indeed separated from the static range.


Anyway I spent yesterday's afternoon rebooting pcp, router, switch , xilinxing the TP (for some reason it did not behave normally - the audio outputs for example although set up to switch off @ power off did not do that - another time the lcd froze,another time it would play but would not produce sound- has happened again in the past),factory resetting the Radio and trying to make it stick with a static ip- seems to work so far, and completely uninstalling squeezeplay and squeezelitetray for now since they appeared to be "stuck" in the available players lms list even when not running.

Preliminary testing shows both Radio and TP behaving normally so far but I've not had enough time to monitor the setup closely yet..fingers crossed

Will report again in the coming days with whatever the outcome.


Again a big thanks to all who shared their wisdom on this(bpa,epoch1970,Mnyb,Michael,Paul)


Cheers

Nikos