Opened 9 years ago
Closed 8 years ago
Last modified 8 years ago
#10890 closed Bug Report - General (fixed)
Mythfrontend tries every 30s to start mythlogserver
Reported by: | JYA | Owned by: | JYA |
---|---|---|---|
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)
Change History (22)
Changed 9 years ago by
Attachment: | config.log added |
---|
Changed 9 years ago by
Attachment: | mythconfig.mak added |
---|
comment:1 Changed 9 years ago by
Owner: | set to beirdo |
---|---|
Status: | new → assigned |
Version: | Unspecified → Master Head |
comment:2 Changed 9 years ago by
comment:3 Changed 9 years ago by
If you change RUNPREFIX=../Resources to RUNPREFIX=.. (in mythconfig.mak), I think your problem will go away.
comment:4 Changed 9 years ago by
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 9 years ago by
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 9 years ago by
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 8 years ago by
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.
Is there any real reason to use the --daemon flag?
comment:8 Changed 8 years ago by
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:
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 8 years ago by
Attachment: | org.mythtv.mythlogserver.plist added |
---|
Changed 8 years ago by
Attachment: | mythlogserver_2012-11-18-115209_localhost.crash added |
---|
OS X crash report
comment:9 Changed 8 years ago by
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.
comment:10 Changed 8 years ago by
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 8 years ago by
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 8 years ago by
Attachment: | logserver-10890.log added |
---|
comment:12 Changed 8 years ago by
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 8 years ago by
Owner: | changed from beirdo to JYA |
---|---|
Status: | assigned → accepted |
comment:14 Changed 8 years ago by
Resolution: | → fixed |
---|---|
Status: | accepted → closed |
comment:15 Changed 8 years ago by
Milestone: | unknown → 0.27 |
---|
In cb1775bd23a2c587bb6f73bfb049410e49720507/mythtv: