Your welcome Thom.  This is an extremely complex system and I am very grateful for all the work everyone has put it in.  I'm glad I can contribute, even if it is just a little.

I've spent much of my day wrapping my head around LMCE_Launch_Manager (LM) and decided to try a few things out.  Because I don't have a dev environment set up I am really unable to do much with LM, except stare at the source incessantly.  So I noticed that there was a lot of logging within the source that doesn't end up in a log.  I also noticed that *some* extra logging shows when you run LM from a console.  So I commented out LM in the boot scripts and logged in on tty1 and ran LM there while capturing output...  Still not all the logging showing but some extra.  The first portion of the log is here:

Code:

=>initialize_Connections()
Opening DB connection..
Successful
Checking if core is up...
Running UpdateAvailableSerialPorts.sh
Requested respawning of new children devices
Spawning new children devices - media
Starting device 21 OnScreen Orbiter
Error when querying device status
Finished spawning new children devices - media
Finished respawning of new children devices
>>Performing autostart if configured..
>>Autostarting core....
Running UpdateAvailableSerialPorts.sh
Starting process /usr/pluto/bin/StartCoreServices.sh
... continues...

The line "Running UpdateAvailableSerialPorts.sh" through to "Finished respawning of new children devices" show that the functions LM::updateScripts and LM::respawnNewChildren are called.  This is happening before the LM::doAutoStart function is called and is the premature execution of orbiter.

There are 2 places in code this looks like it could happen:
1) a call to LMdeviceKeepAlive() <-- this seems rather unlikely given that DCERouter is not running to have sent this msg yet
2) either m_bCoreRunning OR m_bMediaRunning are true in the middle of LM::Initialize

Because LM::respawnNewChildren logs that it's calling LM::startMediaDevices it stands to reason that m_bMediaRunning is TRUE in LM::Initialize (supports #2 above).  As well, because the logs do not show LM::startCoreDevices being called it seems reasonable to assume that m_bCoreRunning is FALSE (especially since the autostart core routines seem to run after LM::respawnNewChildren), **edit: it's also the only way that m_bMediaRunning wouldn't have an opportunity to be set false...

So... My hypothesis at the moment is that m_bMediaRunning is erroneously being set TRUE during one of the LM:initialize_* functions.  I'm not sure what else may or may not be happening in between because what is/isn't logged seems kinda random to me.

Wait... What about this:
m_bMediaRunning is never assigned an initial value and has the possibility of not being assigned a value of FALSE during the LM::initialize_* functions.  m_bMediaRunning can only be set FALSE if m_bCoreRunning is TRUE during LM::initialize_Start (when checkMedia() is called).  So, sketchy again on the C++ but... will the memory location that m_bMediaRunning points to not just contain whatever was in the memory location beforehand?  And if it contains a 1 and m_bMediaRunning *is not* set FALSE somewhere then it could be TRUE?  If this is the case it would be just a matter of setting m_bMediaRunning=false at the top of LM::initialize_Start()...(or somewhere else)?

This could also explain why some people experience the problem and some don't.

I might be completely crazy here...  I've been beating my head into this monitor for a while...  

J.

Thanks for confirming the boot order for me Thom!

I've been digging further into this and am starting to get a good grasp of the lmce boot process.

I have done a near forensic audit of my logs during the incorrect boot process and have narrowed down the issue to occurring within LMCE_Launch_Manager.  My C++ is pretty sketchy so I decided to double check every possible script I could during the boot process.  I couldn't find anything in the scripts which would cause orbiter to load prematurely so I went back to LMCE_Launch_Manager.

Complete LaunchManager.log from an incorrect boot:

Code:

05      09/19/09 10:18:24.919           Detected core as device #1 <0xb77616c0>
05      09/19/09 10:18:30.390           Requested respawning of new children devices <0xb77616c0>
05      09/19/09 10:18:30.546           Failed to open file /usr/pluto/locks/pluto_spawned_local_devices.txt <0xb77616c0>
05      09/19/09 10:18:30.546           Continuing, assuming no devices are running <0xb77616c0>
05      09/19/09 10:18:30.546           Spawning new children devices - media <0xb77616c0>
05      09/19/09 10:18:31.112           Finished spawning new children devices - media <0xb77616c0>
05      09/19/09 10:18:31.123           Finished respawning of new children devices <0xb77616c0>
05      09/19/09 10:18:31.133           Sending  SYSCOMMAND_DEVICE_UP from LM device 1 failed <0xb77616c0>
05      09/19/09 10:18:32.383           Starting process /usr/pluto/bin/StartCoreServices.sh <0xb6dffb90>
05      09/19/09 10:18:48.609           void ClientSocket::Disconnect() on this socket: 0x9540f40 (m_Socket: 9) <0xb6dffb90>

By cross-referencing with pluto.log it seems premature execution of orbiter is occuring between "Spawning new children devices - media <0xb77616c0>" and "Finished spawning new children devices - media <0xb77616c0>".  But these sections of code shouldn't be executing if the Core is not running yet (at least from my understanding of the code)...

So I forced StartCoreServices.sh to execute BEFORE LMCE_Launch_Manager by adding it to Startup_Core-Hybrid.sh right before the call to lmce_launch_manager.sh.  The system seems to boot PERFECTLY (or it seems so to me... I'm still learning).  The following is my complete LaunchManager.log from the new boot:

Code:

05      09/20/09 10:06:08.659           Detected core as device #1 <0xb77f66c0>
05      09/20/09 10:06:13.920           void ClientSocket::Disconnect() on this socket: 0xb6e4b5a8 (m_Socket: 9) <0xb77f66c0>
05      09/20/09 10:06:15.271           Requested respawning of new children devices <0xb77f66c0>
05      09/20/09 10:06:15.548           Failed to open file /usr/pluto/locks/pluto_spawned_local_devices.txt <0xb77f66c0>
05      09/20/09 10:06:15.548           Continuing, assuming no devices are running <0xb77f66c0>
05      09/20/09 10:06:15.549           Spawning new children devices - core <0xb77f66c0>
05      09/20/09 10:06:37.140           Finished spawning new children devices - core <0xb77f66c0>
05      09/20/09 10:06:37.145           Finished respawning of new children devices <0xb77f66c0>

LMCE_Launch_Manager understands that the core is already started and doesn't re-execture StartCoreServices.sh.  Now a "Spawning new children devices - core" executes (because the core is now started) and the "Spawning new children devices - media" section doesn't seem to be executed (but I think it should be).

Now, I am no C++ expert, I'm wondering about an expression in LM.cpp which tests to determine if the spawn devices-media section will execute:

Revision 22269 - LM.cpp - Line 1584

Code:

1584        if ( ( (m_bCoreHere &&m_bCoreRunning) || !m_bCoreHere) && m_bMediaHere && (m_sAutostartMedia=="1" || false) )

Should there not be a space between the && and m_bCoreRunning for the expression to evaluate properly?  If LMCE_Launch_Manager knew the core was not running it wouldn't attempt to execute the spawn devices-media section at this time.  Likewise it *should* execute this section if the core is running (but didn't).

I'm sorry if I'm way off here but the only C++ experience I have is a college course nearly 10 years ago.  I'm willing to keep beating my head into the screen trying to sort this through but this is my best guess right now.

Did someone try to fix #316 with that line?
http://svn.linuxmce.org/trac.cgi/ticket/316

The line is question seems to have been in the source for about 2 years and looks like it is intended to prevent the problem you reference in ticket 316.

J.

After some more investigation it doesn't appear as though /usr/pluto/Spawn_DCERouter.sh is being called more than once.  

It seems that somehow '/usr/pluto/bin/Spawn_Device.sh 21' is being executed before Start_DCERouter.sh, the following is from my /var/log/pluto.log

Code:

1       09/19/09 10:18:21       SetupAudioVideo (server)        ^[[1;00mStarting^[[1;00m
1       09/19/09 10:18:21       SetupAudioVideo (server)        ^[[1;00m'^[[1;00m
1       09/19/09 10:18:21       SetupAudioVideo (server)        ^[[1;00mDBSetting: S Reboot:  Script Path: /usr/pluto/bin/SoundCards_Setup_i8x0.sh^[[1;00m
1       09/19/09 10:18:21       SetupAudioVideo (server)        ^[[1;00mRunning: /usr/pluto/bin/SoundCards_Setup_i8x0.sh S^[[1;00m
1       09/19/09 10:18:21       /usr/pluto/bin/Start_X.sh (server)      ^[[1;00mStarting X server (client: /usr/bin/xfwm4; parms: --compositor=off)^[[1;00m
1       09/19/09 10:18:22       /usr/pluto/bin/Start_X.sh (server)      ^[[1;00mX server: backround; AlphaBlending: 0^[[1;00m
1       09/19/09 10:18:31       /usr/pluto/bin/Spawn_Device.sh 21 (spawning-device)     ^[[1;00m11664 Dev: 21; Already Running list: ^[[1;00m
1       09/19/09 10:18:31       /usr/pluto/bin/Spawn_Device.sh 21 (spawning-device)     ^[[1;00mdevice: 21 ip: localhost cmd_line: LaunchOrbiter.sh^[[1;00m
0       09/19/09 10:18:31       21 (spawning-device)    ^[[1;00mEntering 21^[[1;00m
1       09/19/09 10:18:31       21 (spawning-device)    ^[[1;00mStarting... 1^[[1;00m
1       09/19/09 10:18:31       21 (spawning-device)    ^[[1;00mFound /usr/pluto/bin/LaunchOrbiter.sh^[[1;00m
1       09/19/09 10:18:31       LaunchOrbiter (server)  ^[[1;00mNumber of desktops found: 6 ; desktops activated? 1^[[1;00m
1       09/19/09 10:18:31       LaunchOrbiter (server)  ^[[1;00mPrimary desktop: 4 and secondary desktop 5^[[1;00m
1       09/19/09 10:18:37       /usr/pluto/bin/Start_DCERouter.sh (server)      ^[[1;00mStarting DCERouter^[[1;00m
2       09/19/09 10:18:37       /usr/pluto/bin/Spawn_DCERouter.sh  (server)     ^[[1;33mWriting Version: 2.0.0.44^[[1;00m
1       09/19/09 10:18:37       /usr/pluto/bin/Spawn_DCERouter.sh (server)      ^[[1;00mStarting DCERouter^[[1;00m
1       09/19/09 10:18:37       DCERouter (server)      ^[[1;00mStarting... 1^[[1;00m
1       09/19/09 10:18:44       Spawn_Device.sh 22 (spawning-device)    ^[[1;00m13256 Dev: 22; Already Running list: ^[[1;00m
1       09/19/09 10:18:44       Spawn_Device.sh 22 (spawning-device)    ^[[1;00mdevice: 22 ip: 127.0.0.1 cmd_line: SimplePhone^[[1;00m
1       09/19/09 10:18:44       Spawn_Device.sh 26 (spawning-device)    ^[[1;00m13280 Dev: 26; Already Running list: 22,^[[1;00m
1       09/19/09 10:18:44       Spawn_Device.sh 26 (spawning-device)    ^[[1;00mdevice: 26 ip: 127.0.0.1 cmd_line: MPlayer_Player^[[1;00m
0       09/19/09 10:18:44       22 (spawning-device)    ^[[1;00mEntering 22^[[1;00m

It looks like Device 21 is spawned and then Start_DCERouter.sh/Spawn_DCERouter.sh is called (where it erases the lock file) and when Device 22 is spawned the orbiter (Device 21) is not listed in the 'Already Running list: ' (as the lock file was erased).  Then as Device 26 is spawned #22 is shown in the 'Already Running list: 22m,'.

Then when the the system tries to start Device 21 again a short time later:

Code:

1       09/19/09 10:19:08       /usr/pluto/bin/Spawn_Device.sh 21 (spawning-device)     ^[[1;00m16630 Dev: 21; Already Running list: 22,26,32,25,23,58,15,16,18,19,28,29,30,^[[1;00m
1       09/19/09 10:19:08       /usr/pluto/bin/Spawn_Device.sh 21 (spawning-device)     ^[[1;00mdevice: 21 ip: localhost cmd_line: LaunchOrbiter.sh^[[1;00m
0       09/19/09 10:19:08       21 (spawning-device)    ^[[1;00mEntering 21^[[1;00m
1       09/19/09 10:19:08       21 (spawning-device)    ^[[1;00mStarting... 1^[[1;00m
1       09/19/09 10:19:08       21 (spawning-device)    ^[[1;00mFound /usr/pluto/bin/LaunchOrbiter.sh^[[1;00m
1       09/19/09 10:19:08       LaunchOrbiter (server)  ^[[1;00mNumber of desktops found: 6 ; desktops activated? 1^[[1;00m
1       09/19/09 10:19:08       LaunchOrbiter (server)  ^[[1;00mPrimary desktop: 4 and secondary desktop 5^[[1;00m
1       09/19/09 10:19:10       Spawn_Device.sh 25 (spawning-device)    ^[[1;00m16872 Dev: 25; Already Running list: 22,26,32,25,23,58,15,16,18,19,28,29,30,21,^[[1;00m
1       09/19/09 10:19:10       Spawn_Device.sh 25 (spawning-device)    ^[[1;00m16872 Device 25 was marked as 'running'. Not starting^[[1;00m
1       09/19/09 10:19:10       Spawn_Device.sh 25 (spawning-device)    ^[[1;00m16872 Dev: 25; Exiting because not starting^[[1;00m
1       09/19/09 10:19:11       Spawn_Device.sh 26 (spawning-device)    ^[[1;00m16867 Dev: 26; Already Running list: 22,26,32,25,23,58,15,16,18,19,28,29,30,21,^[[1;00m
1       09/19/09 10:19:11       Spawn_Device.sh 26 (spawning-device)    ^[[1;00m16867 Device 26 was marked as 'running'. Not starting^[[1;00m
1       09/19/09 10:19:11       Spawn_Device.sh 26 (spawning-device)    ^[[1;00m16867 Dev: 26; Exiting because not starting^[[1;00m
1       09/19/09 10:19:11       Spawn_Device.sh 32 (spawning-device)    ^[[1;00m16879 Dev: 32; Already Running list: 22,26,32,25,23,58,15,16,18,19,28,29,30,21,^[[1;00m
1       09/19/09 10:19:11       Spawn_Device.sh 32 (spawning-device)    ^[[1;00m16879 Device 32 was marked as 'running'. Not starting^[[1;00m
1       09/19/09 10:19:11       Spawn_Device.sh 32 (spawning-device)    ^[[1;00m16879 Dev: 32; Exiting because not starting^[[1;00m
1       09/19/09 10:19:12       Spawn_Device.sh 22 (spawning-device)    ^[[1;00m16849 Dev: 22; Already Running list: 22,26,32,25,23,58,15,16,18,19,28,29,30,21,^[[1;00m
1       09/19/09 10:19:12       Spawn_Device.sh 22 (spawning-device)    ^[[1;00m16849 Device 22 was marked as 'running'. Not starting^[[1;00m
1       09/19/09 10:19:12       Spawn_Device.sh 22 (spawning-device)    ^[[1;00m16849 Dev: 22; Exiting because not starting^[[1;00m
1       09/19/09 10:19:12       Spawn_Device.sh 23 (spawning-device)    ^[[1;00m16851 Dev: 23; Already Running list: 22,26,32,25,23,58,15,16,18,19,28,29,30,21,^[[1;00m
1       09/19/09 10:19:12       Spawn_Device.sh 23 (spawning-device)    ^[[1;00m16851 Device 23 was marked as 'running'. Not starting^[[1;00m
1       09/19/09 10:19:12       Spawn_Device.sh 23 (spawning-device)    ^[[1;00m16851 Dev: 23; Exiting because not starting^[[1;00m
1       09/19/09 10:19:12       Spawn_Device.sh 58 (spawning-device)    ^[[1;00m16883 Dev: 58; Already Running list: 22,26,32,25,23,58,15,16,18,19,28,29,30,21,^[[1;00m
1       09/19/09 10:19:12       Spawn_Device.sh 58 (spawning-device)    ^[[1;00m16883 Device 58 was marked as 'running'. Not starting^[[1;00m
1       09/19/09 10:19:12       Spawn_Device.sh 58 (spawning-device)    ^[[1;00m16883 Dev: 58; Exiting because not starting^[[1;00m
2       09/19/09 10:19:20       58 (spawning-device)    ^[[1;33mShutting down... count=1/50 dev=58^[[1;00m
2       09/19/09 10:19:20       32 (spawning-device)    ^[[1;33mShutting down... count=1/50 dev=32^[[1;00m
2       09/19/09 10:19:21       26 (spawning-device)    ^[[1;33mShutting down... count=1/50 dev=26^[[1;00m
2       09/19/09 10:19:21       25 (spawning-device)    ^[[1;33mShutting down... count=1/50 dev=25^[[1;00m
2       09/19/09 10:19:21       23 (spawning-device)    ^[[1;33mShutting down... count=1/50 dev=23^[[1;00m
2       09/19/09 10:19:22       22 (spawning-device)    ^[[1;33mShutting down... count=1/50 dev=22^[[1;00m
2       09/19/09 10:19:23       21 (spawning-device)    ^[[1;33mShutting down... count=1/50 dev=21^[[1;00m

So my fix above of commenting out the 'rm -f ...' line is probably not correct but it works because the lock file is not deleted by Start_DCERouter.sh.  Instead I believe the initial call to 'Spawn_Device.sh 21' probably shouldn't be happening until later.

It seems the next step is to figure out why/where 'Spawn_Device.sh 21' is executing before Start_DCERouter.sh.  Can anyone with more knowledge than I confirm for me that this should not be happening in this order?

Okay, the double orbiter launch on the core has been really bothering me and I've been trying to isolate why/how it is happening.

I have resolved the issue on my system, it appears, but I'm thinking what I found is just a point in the right direction to a deeper issue.

After booting up and having the second orbiter open with the 'this orbiter will be closed message' I was hunting around and noticed that the orbiter (21) was not listed in my /usr/pluto/locks/pluto_spawned_local_devices.txt file.  Actually, there were a lot of devices not listed in this file that should have been.  I did some more digging into the startup procedures and it took me to the file /usr/pluto/Spawn_DCERouter.sh.  In this script exists the following lines:

Code:

# hack: cleaning lockfile on router start to allow
# local devices to start
# TODO: remove this when correct locking will be implemented
rm -f /usr/pluto/locks/pluto_spawned_local_devices.txt

So I commented out the 'rm -f ...' line.  My system now seems to boot normally with the /usr/pluto/locks/pluto_spawned_local_devices.txt file showing all of the spawned devices correctly.  I do not have a second orbiter spawning.

It seems to me that this is an indication that /usr/pluto/Spawn_DCERouter.sh is being called more than once which would delete the pluto_spawned_local_devices.txt file part way through startup.  This causes DCERouter to attempt to reload any devices which had already been loaded.  Hence starting a second orbiter.

Am I on the right track here?  This is a very complex system and I'm not sure where to go now to figure where/why Spawn_DCERouter.sh may be called a second time.

J.

I just remembered there had been a change in procedure on the wiki for the alpha installation:

nVidia Restricted Driver

The installer will now automatically choose and install the correct restricted driver during setup.It will be installed after selecting "OpenGL" on your Media Director in web admin page.

Have you tried selecting OpenGL on the Media Director web admin page? 

...
Hope you understand where we're coming from from, it's a little frustrating to have something working one day, and spending alot of money to purchase more hardware that was proven compatible, to only have your entire setup made useless the next day because of an error i did not make, nor have the equip to fix.
...

The error is all yours, if only just for using alpha software in a production environment.  Yes this needs to be fixed, but simply saying that you made no error is bullshit.

Everyone is being told regularily to install 0810 and that 0710 is no longer supported.  These 2 posts specifically come to mind:

http://forum.linuxmce.org/index.php?topic=8689.msg58754#msg58754
http://forum.linuxmce.org/index.php?topic=8568.msg57650#msg57650

Seems to me that someone testing your alpha software has found a bug that may not have been found otherwise.  How is this the users error?

The more you insult your userbase the less people want to contribute.

J.

Your Xorg log file indicates that the 'vesa' graphics driver is loading instead of the nvidia driver.

# (II) Loading /usr/lib/xorg/modules/drivers//vesa_drv.so
# (II) Module vesa: vendor="X.Org Foundation"
#         compiled for 1.5.0, module version = 1.3.0
#         Module class: X.Org Video Driver
#         ABI class: X.Org Video Driver, version 4.1
# (II) VESA: driver for VESA chipsets: vesa

You will need change a line in the Xorg config file /etc/X11/xorg.conf.  The line which reads:

Code:

           Driver      "vesa"

should be changed to:

Code:

           Driver      "nvidia"

There is an application which can do this for you, I believe it is executed like this:

Code:

$ sudo nvidia-xconfig

You will be asked for your password for the application to run.  Afterwords you should be able to reboot into the AVWizard and select your desired resolution properly.

Even though you are re-installing you may find this issue happens again.  Select the default resolutions in AVWizard until you have updated your drivers and made sure your xorg.conf file is set for the nvidia driver.  After you are sure that the nvidia driver is loading reboot into the AVWizard and then you should be able to select your desired resolution.  This is the procedure I usually follow when installing and upgrading nvidia drivers.

J.

Looks like you're experiencing the same issues many are:

http://forum.linuxmce.org/index.php?topic=8868.0
http://forum.linuxmce.org/index.php?topic=8815.0

J.

J. <phenigma>,
Thank you for the confirmation.

Your welcome.

Two more questions if you don't mind.

1.  my understanding is that the apt-catcher server does not have to be a gateway / router.  That is, it can just sit off a switch between the internet / external firewall / router and the core / dcerouter and traffic does not have to pass through it.  Is that correct? 

Correct.

2.  do you change your repo lists to point to the apt-catcher server?

No repository changes.  The file /etc/apt/apt.conf.d/02proxy (created during the 'pre-install-from-repo.sh' portion of the lmce install) tells aptitude where to find the cache.  The cache acts as a proxy.  Leave your sources.list file alone.

J.

Once installed, to you point back to the main repos, or do you just update your own copy and continue to use that?

Apt-cacher-ng keeps the repositories updated automatically as machines update.

J.

Thank you.  I've thought about putting a switch and an old server on the internet side of lmce and caching there - is that how you do it?  Do you have a recipe that folks can follow?
thanks,
joseph

That's exactly what I've done.  Keep in mind that this is not supported.  It works for me and has significantly reduced bandwidth usage while speeding up installation of lmce or any ubuntu/debian based distro you use regularly.

I have an old pc I use for various purposes that sits on the internet side of the lmce core.  It's running Ubuntu 8.10 and I installed apt-cacher-ng on it using aptitude.

Code:

# aptitude install apt-cacher-ng

Then when I install lmce on my core I follow the instructions on the wiki for installing the Alpha, except that before I execute the pre-install-from-repo.sh script I make a minor modification to the pre-install-common.sh script.  The line I change is:

Code:

    echo 'Acquire::http { Proxy "http://localhost:3142"; };' > /etc/apt/apt.conf.d/02proxy

I change the word localhost and put the IP of my outside server instead.  I save the modified script and proceed to run the pre-install-from-repo.sh script to begin the lmce installation.

The first time you install after performing these steps will take the same length of time it always has.  On subsequent installations any unchanged packages will be grabbed from your cache rather than the lmce repository.

90-95% of the lmce install now uses the cache on my outside server rather than the lmce repository.  All repository downloads go through the outside server and only new/changed/updated packages are fetched from the lmce repository whenever aptitude/apt-get are used.  All of my mds automatically use my outside server's repository cache as well with this method.

J.

The number of times I'm re-building my core, I too would LOVE a DVD or even a way of setting up a local copy of the repository.

The repository can be cached .  This can be accomplished by setting up apt-cacher-ng on a seperate machine outside the lmce network.  The install script must then be altered each time a new install is attempted.

I have been doing this for a few months as I was exceeding my ISPs DL caps and needed to reduce my usage.  I now point all of my ubuntu machines to my cache.  LMCE installs are a little quicker at 100Mbs.

J.

I've been waiting for an nvidia graphics based touchscreen.  It is exactly what my wife wants for the kitchen.

I believe the command you want is 'update-rc.d ....'.

J.