minimyth reading options defined in minimyth.conf unreliaby

Help with booting MiniMyth

Moderator: Pablo

Post Reply
thekorn
Contributor
Posts: 71
Joined: Wed Dec 31, 2008 8:45 am

minimyth reading options defined in minimyth.conf unreliaby

Post by thekorn » Fri Jan 02, 2009 5:23 pm

So with a maddening amount of non regularity, occasionally I'll boot up a minimyth box and get this in /var/log/minimyth.log:

Code: Select all

minimyth@?:/var/log $ more minimyth.err.log
error: 'TCode' (or 'MM_DHCP_TCODE') not configured.
error: 'NTP Servers' (or 'MM_DHCP_NTP_SERVERS') not configured.
error: 'Host Name' (or 'MM_DHCP_HOST_NAME') not configured.
error: check '/var/log/minimyth.err.log' for further details.
What's strange is that all of those items are defined in my minimyth.conf file...

Code: Select all


(anything marked [redacted] has a value, but I've stripped it for obvious reasons)

MM_DHCP_HOST_NAME='myth-front-1a'
MM_DHCP_TCODE='America/Chicago'
MM_DHCP_NTP_SERVERS=[redacted]
MM_ACPI_EVENT_BUTTON_POWER='off'
MM_VIDEO_DEINTERLACER='auto'
MM_X_SCREENSAVER='xscreensaver'
MM_X_SCREENSAVER_TIMEOUT='30'
MM_X_SCREENSAVER_HACK='sleep'
MM_X_OUTPUT_DVI='auto'
MM_MASTER_SERVER=[redacted]
MM_MASTER_DBPASSWORD=[redacted]
MM_PLUGIN_OPTICAL_DISK_ENABLED='no'
MM_THEME_NAME='blootubelite-wide'
MM_THEMEOSD_NAME='Retro-OSD'
MM_VIDEO_ASPECT_RATIO='16:9'
MM_SECURITY_FETCH_CREDENTIALS_CIFS='yes'
MM_LIRC_FETCH_LIRCRC='yes'

And here's the really weird thing... When it fails, all I do is walk over, kick the reset button on the box (changing absolutely nothing), and the next time it'll boot straight in to minimyth! Well let me qualify that... sometimes it'll fail two or three times in a row, but if I hit a stretch of bad luck eventually after I kick the reset button enough times it'll boot into minimyth.

So it seems as though my minimyth.conf file is fine. (It wouldn't ever work if it was bad.) But there seems to be some sort of race condition between pulling minimyth.conf and reading minimyth.conf. (Maybe add a requirement of the final config line being MM_CONFIG_FILE_COMPLETE='true', and if you don't see that line wait and do not process the config file, with a timeout of fifteen seconds? Ugly but it'd work.)

(Note: even when reading the config file fails, the whole minimyth.conf is actually processed. For example, if I look at /etc/lircrc , it's the lircrc that's been pulled from the tftp server.)

Any hints or suggestions? Thanks in advance!

(I'm running minimyth 0.21.0-61.)

thekorn
Contributor
Posts: 71
Joined: Wed Dec 31, 2008 8:45 am

Post by thekorn » Sat Jan 03, 2009 6:07 am

OK, so here's some more info I've been able to dig up. I looked at /var/messages on a good and a bad boot. And the problem seems to be when udhcpc is started for the second time....


Here is the messages file from a BAD boot:

Code: Select all

Jan  3 04:33:07 (none) syslog.info syslogd started: BusyBox v1.11.3
Jan  3 04:33:07 (none) daemon.info init: Entering runlevel: 5
Jan  3 04:33:07 (none) local0.info minimyth: starting splash screen
Jan  3 04:33:07 (none) local0.info minimyth: configuring shared libraries ...
Jan  3 04:33:07 (none) local0.info minimyth: starting loopback network interface ...
Jan  3 04:33:07 (none) auth.notice portmap[784]: Only binding to LOOPBACK address!
Jan  3 04:33:07 (none) local0.info minimyth: starting DHCP client ...
Jan  3 04:33:07 (none) local0.info udhcpc[797]: udhcpc (v1.11.3) started
Jan  3 04:33:07 (none) local0.info udhcpc[797]: Sending discover...
Jan  3 04:33:10 (none) local0.info udhcpc[797]: Sending discover...
Jan  3 04:33:10 (none) local0.info udhcpc[797]: Sending select for 172.18.0.111...
Jan  3 04:33:10 (none) local0.info udhcpc[797]: Lease of 172.18.0.111 obtained, lease time 86400
Jan  3 04:33:11 (none) local0.info minimyth: loading kernel modules (automatic) ...
Jan  3 04:33:13 (none) local0.info minimyth: fetching configuration file  ...
Jan  3 04:33:13 (none) local0.info minimyth: checking for obsolete variables ...
Jan  3 04:33:14 (none) local0.info minimyth: stopping DHCP client ...
Jan  3 04:33:14 (none) local0.info udhcpc[888]: Received SIGTERM
Jan  3 04:33:14 (none) local0.info minimyth: processing configuration file ...
Jan  3 04:33:14 (none) local0.info minimyth: fetched MiniMyth read-only configuration file '/lircrc'
Jan  3 04:33:14 (none) local0.info minimyth:   by fetching 'tftp://172.18.0.105/conf/default/lircrc'
Jan  3 04:33:14 (none) local0.info minimyth:   to local file '/etc/lircrc'.
[more truncated because it's no longer interesting after here]
And here is the same snipped of /var/messages from a GOOD boot:

Code: Select all

Jan  3 04:42:19 (none) syslog.info syslogd started: BusyBox v1.11.3
Jan  3 04:42:19 (none) daemon.info init: Entering runlevel: 5
Jan  3 04:42:19 (none) local0.info minimyth: starting splash screen
Jan  3 04:42:19 (none) local0.info minimyth: configuring shared libraries ...
Jan  3 04:42:19 (none) local0.info minimyth: starting loopback network interface ...
Jan  3 04:42:19 (none) auth.notice portmap[784]: Only binding to LOOPBACK address!
Jan  3 04:42:19 (none) local0.info minimyth: starting DHCP client ...
Jan  3 04:42:19 (none) local0.info udhcpc[797]: udhcpc (v1.11.3) started
Jan  3 04:42:19 (none) local0.info udhcpc[797]: Sending discover...
Jan  3 04:42:22 (none) local0.info udhcpc[797]: Sending discover...
Jan  3 04:42:22 (none) local0.info udhcpc[797]: Sending select for 172.18.0.111...
Jan  3 04:42:22 (none) local0.info udhcpc[797]: Lease of 172.18.0.111 obtained, lease time 86400
Jan  3 04:42:23 (none) local0.info minimyth: loading kernel modules (automatic) ...
Jan  3 04:42:26 (none) local0.info minimyth: fetching configuration file  ...
Jan  3 04:42:26 (none) local0.info minimyth: checking for obsolete variables ...
Jan  3 04:42:26 (none) local0.info minimyth: stopping DHCP client ...
Jan  3 04:42:26 (none) local0.info udhcpc[888]: Received SIGTERM
Jan  3 04:42:26 (none) local0.info minimyth: starting DHCP client ...
Jan  3 04:42:26 (none) local0.info udhcpc[2134]: udhcpc (v1.11.3) started
Jan  3 04:42:26 (none) local0.info udhcpc[2134]: Sending discover...
Jan  3 04:42:26 (none) local0.info udhcpc[2134]: Sending select for 172.18.0.111...
Jan  3 04:42:26 (none) local0.info udhcpc[2134]: Lease of 172.18.0.111 obtained, lease time 86400
Jan  2 22:42:26 (none) local0.info minimyth: processing configuration file ...
Jan  2 22:42:26 (none) local0.info minimyth: fetched MiniMyth read-only configuration file '/lircrc'
Jan  2 22:42:26 (none) local0.info minimyth:   by fetching 'tftp://172.18.0.105/conf/default/lircrc'
Jan  2 22:42:26 (none) local0.info minimyth:   to local file '/etc/lircrc'.
[more truncated because it's no longer interesting after here]

They look identical, except in the bad boot it looks like udhcpc doesn't re-start.

On a good boot, /var/log/udhcpc is empty. On a bad boot, /var/log/udhcpc contains:

Code: Select all

minimyth@?:/var/log $ cat udhcpc
udhcpc (v1.11.3) started
ifconfig: SIOCSIFBRDADDR: Cannot assign requested address
Sending discover...
Sending discover...
Sending select for 172.18.0.111...
Lease of 172.18.0.111 obtained, lease time 86400
So it certainly looks like the problem is udhcpc, but... why? And is there a way to work around it? (My guess is that the first instance of udhcpc hasn't finished shutting down before minimyth tries to fire up the second instance, but that's just a wild hare guess.)

Pablo
Site Admin
Posts: 4182
Joined: Tue Dec 14, 2004 2:13 am
Location: La Jolla
Contact:

Post by Pablo » Sun Jan 04, 2009 12:02 am

Thank you for taking the time to help troubleshoot the problem.

The DHCP client is restarted in order to pick up any DHCP override variables (MM_DHCP_*) that are in minimyth.conf.

I believe the best solution is to not run the DHCP client continuously until after minimyth.conf is retrieved and the DHCP override variables are processed. Before that, rather than starting the DHCP client in run continuously mode, MiniMyth can start the DHCP client in run once (get a DHCP lease) and quit. That way, there should at least be no issue with the DHCP client not terminating before restarting.

I have committed the above change and it will be in the next test build. I will post to this thread once I have uploaded the test build.
MiniMyth running on an Acer ApireRevo 3610 and a Zotac ZBOX-ID80-U. Find out more at my MythTV page.

Pablo
Site Admin
Posts: 4182
Joined: Tue Dec 14, 2004 2:13 am
Location: La Jolla
Contact:

Post by Pablo » Sun Jan 04, 2009 6:46 am

A new test build is available: 0.21.0-63b2. It has the mentioned DHCP changes. Could you let me know whether or not it fixes the problem?
MiniMyth running on an Acer ApireRevo 3610 and a Zotac ZBOX-ID80-U. Find out more at my MythTV page.

thekorn
Contributor
Posts: 71
Joined: Wed Dec 31, 2008 8:45 am

Post by thekorn » Sun Jan 04, 2009 4:58 pm

That looks to have solved it! I put in 0.21.0-63b2, and booted it successfully ten times in a row without incident.

Thanks!

Post Reply