Modify
Warning Please read the Ticket HowTo before creating or commenting on a ticket. Failure to do so may cause your ticket to be rejected or result in a slower response.

Opened 22 months ago

Closed 13 months ago

Last modified 12 months ago

#10890 closed Bug Report - General (fixed)

Mythfrontend tries every 30s to start mythlogserver

Reported by: jyavenard Owned by: jyavenard
Priority: minor Milestone: 0.27
Component: MythTV - General Version: Master Head
Severity: medium Keywords:
Cc: Ticket locked: no

Description

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.

Attachments (7)

config.log (3.1 KB) - added by jyavenard 22 months ago.
mythconfig.mak (40.7 KB) - added by jyavenard 22 months ago.
org.mythtv.mythlogserver.plist (719 bytes) - added by Craig Treleaven <ctreleaven@…> 17 months ago.
mythlogserver_launchd.log (7.7 KB) - added by Craig Treleaven <ctreleaven@…> 17 months ago.
log with comments added
mythlogserver_2012-11-18-115209_localhost.crash (43.4 KB) - added by Craig Treleaven <ctreleaven@…> 17 months ago.
OS X crash report
MythBackend_daemon_crash.txt (48.6 KB) - added by dgktkr 15 months ago.
MythBackend_daemon_crash
logserver-10890.log (919 bytes) - added by jyavenard 15 months ago.

Download all attachments as: .zip

Change History (22)

Changed 22 months ago by jyavenard

Changed 22 months ago by jyavenard

comment:1 Changed 22 months ago by beirdo

  • Owner set to beirdo
  • Status changed from new to assigned
  • Version changed from Unspecified to Master Head

comment:2 Changed 22 months ago by 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

comment:3 Changed 22 months ago by beirdo

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

comment:4 Changed 22 months ago by 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

comment:5 Changed 22 months ago by 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

comment:6 Changed 22 months ago by 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.

comment:7 Changed 18 months ago by 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?

comment:8 Changed 17 months ago by 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.

Changed 17 months ago by Craig Treleaven <ctreleaven@…>

Changed 17 months ago by Craig Treleaven <ctreleaven@…>

log with comments added

Changed 17 months ago by Craig Treleaven <ctreleaven@…>

OS X crash report

comment:9 Changed 15 months ago by 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.

Changed 15 months ago by dgktkr

MythBackend_daemon_crash

comment:10 Changed 15 months ago by 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

comment:11 Changed 15 months ago by 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

Changed 15 months ago by jyavenard

comment:12 Changed 15 months ago by 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

comment:13 Changed 13 months ago by jyavenard

  • Owner changed from beirdo to jyavenard
  • Status changed from assigned to accepted

comment:14 Changed 13 months ago by Jean-Yves Avenard <jyavenard@…>

  • Resolution set to fixed
  • Status changed from accepted to closed

In 47561dcf966350278fd0bb07e0d7eee7f1cab22e/mythtv:

Do not try to fork in the background

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

Fixes #10890

comment:15 Changed 12 months ago by wagnerrp

  • Milestone changed from unknown to 0.27

Add Comment

Modify Ticket

Action
as closed .
The resolution will be deleted. Next status will be 'new'.
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.