Mythfrontend tries every 30s to start mythlogserver

[jyavenard]

Log is full of:

2012-07-07 10:49:43.087910 D  Launching: /Users/jyavenard/Work/mythtv/.osx-packager/build/bin/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog
2012-07-07 10:49:43.089862 I  Managed child (PID: 14550) has started! * command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, timeout=0
2012-07-07 10:49:43.098787 E  Structure for child PID 14550 already deleted!
2012-07-07 10:50:13.139492 I  Starting mythlogserver
2012-07-07 10:50:13.139592 D  Launching: /Users/jyavenard/Work/mythtv/.osx-packager/build/bin/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog
2012-07-07 10:50:13.141859 I  Managed child (PID: 14605) has started! * command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, timeout=0
2012-07-07 10:50:13.150512 E  Structure for child PID 14605 already deleted!
2012-07-07 10:50:43.206420 I  Starting mythlogserver
2012-07-07 10:50:43.206547 D  Launching: /Users/jyavenard/Work/mythtv/.osx-packager/build/bin/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog
2012-07-07 10:50:43.208955 I  Managed child (PID: 14670) has started! * command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, timeout=0
2012-07-07 10:50:43.219381 E  Structure for child PID 14670 already deleted!
2012-07-07 10:51:13.266995 I  Starting mythlogserver
2012-07-07 10:51:13.267084 D  Launching: /Users/jyavenard/Work/mythtv/.osx-packager/build/bin/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog
2012-07-07 10:51:13.269263 I  Managed child (PID: 17469) has started! * command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, timeout=0
2012-07-07 10:51:13.280420 E  Structure for child PID 17469 already deleted!

note that the path to mythlogserver is incorrect, it should be /Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver, but somehow an extra bin is added.

[Gavin Hurlbut <ghurlbut@…>]

In cb1775bd23a2c587bb6f73bfb049410e49720507/mythtv:

Make relative prefix logging more verbose

We weren't actually checking the results of the cd() call. Now log an error
if it fails.

Refs #10890

[beirdo]

If you change RUNPREFIX=../Resources to RUNPREFIX=.. (in mythconfig.mak), I think your problem will go away.

[jyavenard]

I set Resources to be a symbolic link to the proper folder, so I don't have to change the mac build script.

It still restart constantly, with not much info being available

2012-07-17 18:10:43.395617 I  Starting mythlogserver
2012-07-17 18:10:43.395790 D  Launching: /Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog
2012-07-17 18:10:43.397564 I  Managed child (PID: 86856) has started! * command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, timeout=0
2012-07-17 18:10:43.464207 I  Managed child (PID: 86856) has exited! command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, status=0, result=0
2012-07-17 18:10:49.521142 I  Starting mythlogserver
2012-07-17 18:10:49.521270 D  Launching: /Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog
2012-07-17 18:10:49.522834 I  Managed child (PID: 86859) has started! * command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, timeout=0
2012-07-17 18:10:49.590192 I  Managed child (PID: 86859) has exited! command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, status=0, result=0
2012-07-17 18:10:55.595872 I  Starting mythlogserver
2012-07-17 18:10:55.596083 D  Launching: /Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog
2012-07-17 18:10:55.597805 I  Managed child (PID: 86861) has started! * command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, timeout=0
2012-07-17 18:10:55.664762 I  Managed child (PID: 86861) has exited! command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, status=0, result=0
2012-07-17 18:11:01.721206 I  Starting mythlogserver
2012-07-17 18:11:01.721403 D  Launching: /Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog
2012-07-17 18:11:01.723220 I  Managed child (PID: 86863) has started! * command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, timeout=0
2012-07-17 18:11:01.789832 I  Managed child (PID: 86863) has exited! command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, status=0, result=0
2012-07-17 18:11:07.796573 I  Starting mythlogserver
2012-07-17 18:11:07.796779 D  Launching: /Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog
2012-07-17 18:11:07.798501 I  Managed child (PID: 86865) has started! * command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, timeout=0
2012-07-17 18:11:07.865918 I  Managed child (PID: 86865) has exited! command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, status=0, result=0
2012-07-17 18:11:13.970287 I  Starting mythlogserver
2012-07-17 18:11:13.970443 D  Launching: /Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog
2012-07-17 18:11:13.971812 I  Managed child (PID: 86868) has started! * command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, timeout=0
2012-07-17 18:11:14.040186 I  Managed child (PID: 86868) has exited! command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, status=0, result=0
Z2012-07-17 18:11:20.093855 I  Starting mythlogserver
2012-07-17 18:11:20.093966 D  Launching: /Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog
2012-07-17 18:11:20.095588 I  Managed child (PID: 86872) has started! * command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, timeout=0
2012-07-17 18:11:20.163803 I  Managed child (PID: 86872) has exited! command=/Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --daemon  --verbose general,audio,playback,libav,system --loglevel debug --nodblog, status=0, result=0

[jyavenard]

Trying to start it by hand...

$ DYLD_FRAMEWORK_PATH=~/Work/mythtv/.osx-packager/build/lib DYLD_LIBRARY_PATH=~/Work/mythtv/.osx-packager/build/lib /Users/jyavenard/Work/mythtv/.osx-packager/build/bin/mythlogserver --verbose general,audio,playback,libav,system --loglevel debug --nodblog --daemon
jyaimac:build jyavenard$ Handling Abort trap: 6

When it's started without --daemon, it starts okay and doesn't prematurely exit

[beirdo]

Wonderful, so it seems to be aborting somewhere in the daemon mode handling? Could you try running the backend in --daemon mode to see if you get the same results? Just wondering where the issue may be. It does seem to be OSX-specific, so far.

[mythtv@…]

Launchd is the approved way to kick off server processes in OSX. It expects, generally, to kick off processes on an "as-needed" basis. This bug may well have to do with running afoul of launchd policy.
Among the "Required Behaviors" of launchd processes is the following:

You must not daemonize your process. This includes calling
the daemon function, calling fork followed by exec, or calling
fork followed by exit. If you do, launchd thinks your process
has died. Depending on your property list key settings, launchd
will either keep trying to relaunch your process until it gives up
(with a “respawning too fast” error message) or will be unable to
restart it if it really does die.

​http://developer.apple.com/library/mac/#documentation/MacOSX/Conceptual/BPSystemStartup/Chapters/CreatingLaunchdJobs.html

Is there any real reason to use the --daemon flag?

[Craig Treleaven <ctreleaven@…>]

Summary -

The good news--launchd on OS X WILL start up mythlogserver when another myth program accesses TCP 35327 (used by the myth's logging system).

The bad news--no logs are created except for mythlogserver. mythlogserver times out (after 5 minutes) even though a Myth app is running. mythlogserver crashes after the 5 minute timeout for some reason.

Details -

I created a launchd plist--no --daemon flag--for mythlogserver, attached, based on documentation from Apple:

​http://developer.apple.com/library/mac/#documentation/MacOSX/Conceptual/BPSystemStartup/Chapters/CreatingLaunchdJobs.html#//apple_ref/doc/uid/10000172i-SW7-BCIEDDBJ

I installed myth 0.26 (code as of ~Oct 10, 2012) using an unreleased MacPorts? portfile. Loaded the plist with:

sudo launchctl load -w /Library/LaunchDaemons?/org.mythtv.mythlogserver.plist

Note that mythlogserver is not launched at this point. Then started mythtv-setup. Immediately, mythlogserver started up. The launchd plist redirects std out and std err to a file and mythlogserver began writing it's log to the normal log file. However, no log file appeared for mythtv-setup. Log from launched is attached and I've added comments about the crashes, etc. One of the crash reports is attached--the others are substantially the same.

Later, I quit and relaunched mythtv-setup while mythlogserver was already running. From watching Activity Monitor, two copies of mythlogserver appeared with one copy disappearing almost immediately.

Please let me know if there are additional tests that I should run.

[Craig Treleaven <ctreleaven@…>]

log with comments added

[Craig Treleaven <ctreleaven@…>]

OS X crash report

[Craig Treleaven <ctreleaven@…>]

I tried removing the '--daemon' flag:

​https://github.com/MythTV/mythtv/blob/fixes/0.26/mythtv/libs/libmythbase/logging.cpp#L493

I then used mythtv-setup to test. Starting mythtv-setup does cause mythlogserver to launch. HOWEVER, when I tried to exit mythtv-setup, it appeared to hang. I then used Console.app to force mythlogserver to quit and then mythtv-setup immediately exited. I believe mythtv-setup was waiting for mythlogserver to 'finish' and exit!!

Obviously, this isn't very friendly behaviour for folks that want to run a remote frontend and quit when finished.

It appears to me that using OS X launchd services would be the right way to launch and stop mythlogserver. However, there would have to be a bunch of conditional code to make that work. Maybe somebody has a better strategy.

As I see it, the OS X port is dead in the water because of this.

[dgktkr]

MythBackend_daemon_crash

[xdrcft@…]

beirdo

You requested that someone try running the executable "./MythBackend? --daemon" in a terminal. I've done that and it crashed right away. I've uploaded the crash log into the attachment area above.

MythBackend? seems to run OK, when started in the same way, but without the "--daemon". But in that case, mythlogserver is periodically restarted, after which that executable crashes. (Every 6 seconds on my setup, with a complaint "USING_FORK_WITHOUT_EXEC_IS_NOT_SUPPORTED_BY_FILE_MANAGER".)

mythlogserver seems to run OK when started from the command line on its own ("./mythlogsrver"), but announces after 5 minutes that the idle clock has run out, then goes away with "Segmentation fault: 11".

dgktkr

[xdrcft@…]

I've done some more experimenting and have found a way to get mythlogserver to
do its job on OS-X in a way that seems perfectly normal.

1) Edit osx-packager-qtsdk.pl so that the mythlogserver binary is included in the
MythBackend?.app bundle (adding it to the list at around line 1910), and execute
that Perl script to build the app.

2) Put the following mythlogserver.plist in ~/Library/LaunchAgents/?:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
        <key>KeepAlive</key>
	<true/>
	<key>Label</key>
	<string>mythlogserver</string>
	<key>ProgramArguments</key>
	<array>
		<string>/Applications/MythTV/MythBackend.app/Contents/MacOS/mythlogserver</string>
	</array>
</dict>
</plist>

3) Put the following MythBackend?.plist in ~/Library/LaunchAgents/? :

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
        <key>KeepAlive</key>
	<true/>
	<key>Label</key>
	<string>MythBackend</string>
	<key>ProgramArguments</key>
	<array>
		<string>/Applications/MythTV/MythBackend.app/Contents/MacOS/MythBackend</string>
                <string>--logpath</string>
		<string>/Users/dgktkr/Library/Logs/MythBackend</string>
	</array>
</dict>
</plist>

Now when I boot up and log in, MythBackend? and mythlogserver are running
and logs are written in the expected places. And neither MythBackend? nor
mythlogserver crash.

I tried running mythlogserver without the KeepAlive? option in the plist,
and indeed, the process goes away and returns as needed for logging,
but looking at cpu usage in Activity Monitor indicates that significant
effort takes place to build up and tear down the process. KeepAlive? keeps the
process there all the time, but seems to put less of a load on the system.

dgktkr

[jyavenard]

There's really no need to daemonize mythlogserver when started by the backend as it has already forked to start mythlogserver.

According to Apple documentation, a call to fork must be followed by an exec.
The daemon API doesn't do that and the started application is then killed.

This patch disable the daemon option (just ignores it).

Please try and see how that works for you. I find no downside to that approach. logging works well here

[Jean-Yves Avenard <jyavenard@…>]

In 47561dcf966350278fd0bb07e0d7eee7f1cab22e/mythtv:

Do not try to fork in the background

There is no much point as we've already forked.

Fixes #10890