gungfujoe
June 19th, 2009, 11:20 PM
I'm using Mythbuntu 9.04 x86 with an HDHomeRun and an ATI Radeon 3450-based video card. After finally getting Mythbackend to recognize my HDHomeRun (have to restart the backend, since it loads before the system gets an IP address), I restarted the frontend, hit "Watch TV," and got a blank screen, followed a few seconds later by "Error was encountered while displaying video."
Looking at the log file (appended below), it looks as if the backend doesn't have permission to work with the mpg files it needs to create to display a TV feed. I restarted the backend with "sudo /etc/init.d/mythtv-backend restart", and looking at the process list (ps -A u | grep myth), I see that the backend is indeed running under the "mythtv" user, and not under my own login. And when I look in /var/lib/mythtv/recordings, I see a handful of 0-byte MPG files owned by mythtv. Mythtv also owns the directory, which has 775 (drwxrwsr-x) permissions.
What gives? I was using MythTV 8.10 on here before, and while I had a number of serious problems preventing me from using it (I replaced the motherboard and installed 9.04 from scratch), I never encountered anything like this.
Starting up as the master server.
2009-06-19 22:58:34.931 HDHRChan(ffffffff/0): device found at address 192.168.1.11
2009-06-19 22:58:34.936 New DB connection, total: 3
2009-06-19 22:58:34.942 Connected to database 'mythconverg' at host: localhost
2009-06-19 22:58:35.027 New DB scheduler connection
2009-06-19 22:58:35.028 Connected to database 'mythconverg' at host: localhost
2009-06-19 22:58:35.035 MediaServer:: Loopback address specified - 127.0.0.1. Disabling UPnP
2009-06-19 22:58:35.036 Main::Registering HttpStatus Extension
2009-06-19 22:58:35.044 mythbackend version: 0.21.20080304-1 www.mythtv.org
2009-06-19 22:58:35.050 Enabled verbose msgs: important general
2009-06-19 22:58:35.059 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2009-06-19 22:58:38.031 Reschedule requested for id -1.
2009-06-19 22:58:38.044 Scheduled 0 items in 0.0 = 0.01 match + 0.01 place
2009-06-19 22:58:38.047 Seem to be woken up by USER
2009-06-19 22:58:55.031 Expiring 0 MBytes for 2080 @ Fri Jun 19 20:59:53 2009 => Unknown
2009-06-19 22:58:55.036 Expiring 0 MBytes for 2080 @ Fri Jun 19 20:59:56 2009 => Unknown
2009-06-19 22:58:55.038 Expiring 0 MBytes for 2080 @ Fri Jun 19 21:00:07 2009 => Unknown
2009-06-19 22:58:55.042 Expiring 0 MBytes for 2080 @ Fri Jun 19 21:00:09 2009 => Unknown
2009-06-19 22:58:58.045 Error deleting '/var/lib/mythtv/recordings/2080_20090619205953.mpg' could not open
eno: Permission denied (13)
2009-06-19 22:58:58.049 Delete Error '/var/lib/mythtv/recordings/2080_20090619205953.mpg'
eno: Permission denied (13)
2009-06-19 22:58:58.050 Error deleting file: /var/lib/mythtv/recordings/2080_20090619205953.mpg. Keeping metadata in database.
2009-06-19 22:58:58.054 Error deleting '/var/lib/mythtv/recordings/2080_20090619205956.mpg' could not open
eno: Permission denied (13)
2009-06-19 22:58:58.059 Delete Error '/var/lib/mythtv/recordings/2080_20090619205956.mpg'
eno: Permission denied (13)
2009-06-19 22:58:58.062 Error deleting file: /var/lib/mythtv/recordings/2080_20090619205956.mpg. Keeping metadata in database.
2009-06-19 22:58:58.070 Error deleting '/var/lib/mythtv/recordings/2080_20090619210007.mpg' could not open
eno: Permission denied (13)
2009-06-19 22:58:58.075 Delete Error '/var/lib/mythtv/recordings/2080_20090619210007.mpg'
eno: Permission denied (13)
2009-06-19 22:58:58.079 Error deleting file: /var/lib/mythtv/recordings/2080_20090619210007.mpg. Keeping metadata in database.
2009-06-19 22:58:58.086 Error deleting '/var/lib/mythtv/recordings/2080_20090619210009.mpg' could not open
eno: Permission denied (13)
2009-06-19 22:58:58.091 Delete Error '/var/lib/mythtv/recordings/2080_20090619210009.mpg'
eno: Permission denied (13)
2009-06-19 22:58:58.094 Error deleting file: /var/lib/mythtv/recordings/2080_20090619210009.mpg. Keeping metadata in database.
2009-06-19 22:59:30.225 MainServer::HandleAnnounce Monitor
2009-06-19 22:59:30.227 adding: HTPC as a client (events: 0)
2009-06-19 22:59:30.228 MainServer::HandleAnnounce Monitor
2009-06-19 22:59:30.228 adding: HTPC as a client (events: 1)
2009-06-19 22:59:30.238 MainServer::HandleAnnounce Playback
2009-06-19 22:59:30.267 adding: HTPC as a client (events: 0)
2009-06-19 22:59:30.317 TVRec(1): Changing from None to WatchingLiveTV
2009-06-19 22:59:30.320 TVRec(1): HW Tuner: 1->1
2009-06-19 22:59:31.371 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 15 min
2009-06-19 22:59:32.492 Finished recording Unknown: channel 2080
2009-06-19 22:59:33.514 Finished recording Unknown: channel 2080
2009-06-19 22:59:33.535 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 15 min
2009-06-19 22:59:33.578 Using runtime prefix = /usr
2009-06-19 22:59:33.583 Empty LocalHostName.
2009-06-19 22:59:33.584 Using localhost value of HTPC
2009-06-19 22:59:33.588 New DB connection, total: 1
2009-06-19 22:59:33.592 Connected to database 'mythconverg' at host: localhost
2009-06-19 22:59:33.593 Closing DB connection named 'DBManager0'
2009-06-19 22:59:33.595 Connected to database 'mythconverg' at host: localhost
2009-06-19 22:59:33.601 New DB connection, total: 2
2009-06-19 22:59:33.605 Connected to database 'mythconverg' at host: localhost
2009-06-19 22:59:33.646 Current Schema Version: 1214
2009-06-19 22:59:33.650 Preview Error: Previewer file '/var/lib/mythtv/recordings/2080_20090619225930.mpg' is not valid.
2009-06-19 22:59:33.670 Preview Error: Run() file not local: '/var/lib/mythtv/recordings/2080_20090619225930.mpg'
2009-06-19 22:59:33.677 Preview Error: Preview process not ok.
fileinfo(/var/lib/mythtv/recordings/2080_20090619225930.mpg.png) exists: 0 readable: 0 size: 0
2009-06-19 22:59:40.048 TVRec(1): Changing from WatchingLiveTV to None
2009-06-19 22:59:41.044 Finished recording Unknown: channel 2080
2009-06-19 22:59:55.044 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2009-06-19 23:00:55.053 Expiring 0 MBytes for 2080 @ Fri Jun 19 20:59:53 2009 => Unknown
2009-06-19 23:00:55.054 Expiring 0 MBytes for 2080 @ Fri Jun 19 20:59:56 2009 => Unknown
2009-06-19 23:00:55.057 Expiring 0 MBytes for 2080 @ Fri Jun 19 21:00:07 2009 => Unknown
2009-06-19 23:00:55.059 Expiring 0 MBytes for 2080 @ Fri Jun 19 21:00:09 2009 => Unknown
2009-06-19 23:00:58.060 Error deleting '/var/lib/mythtv/recordings/2080_20090619205953.mpg' could not open
eno: Permission denied (13)
2009-06-19 23:00:58.064 Delete Error '/var/lib/mythtv/recordings/2080_20090619205953.mpg'
eno: Permission denied (13)
2009-06-19 23:00:58.077 Error deleting file: /var/lib/mythtv/recordings/2080_20090619205953.mpg. Keeping metadata in database.
2009-06-19 23:00:58.082 Error deleting '/var/lib/mythtv/recordings/2080_20090619205956.mpg' could not open
eno: Permission denied (13)
2009-06-19 23:00:58.086 Delete Error '/var/lib/mythtv/recordings/2080_20090619205956.mpg'
eno: Permission denied (13)
2009-06-19 23:00:58.095 Error deleting file: /var/lib/mythtv/recordings/2080_20090619205956.mpg. Keeping metadata in database.
2009-06-19 23:00:58.102 Error deleting '/var/lib/mythtv/recordings/2080_20090619210007.mpg' could not open
eno: Permission denied (13)
2009-06-19 23:00:58.107 Delete Error '/var/lib/mythtv/recordings/2080_20090619210007.mpg'
eno: Permission denied (13)
2009-06-19 23:00:58.114 Error deleting file: /var/lib/mythtv/recordings/2080_20090619210007.mpg. Keeping metadata in database.
2009-06-19 23:00:58.126 Error deleting '/var/lib/mythtv/recordings/2080_20090619210009.mpg' could not open
eno: Permission denied (13)
2009-06-19 23:00:58.136 Delete Error '/var/lib/mythtv/recordings/2080_20090619210009.mpg'
eno: Permission denied (13)
2009-06-19 23:00:58.145 Error deleting file: /var/lib/mythtv/recordings/2080_20090619210009.mpg. Keeping metadata in database.
2009-06-19 23:01:10.231 HDHRChan(ffffffff/0): device found at address 192.168.1.11
Looking at the log file (appended below), it looks as if the backend doesn't have permission to work with the mpg files it needs to create to display a TV feed. I restarted the backend with "sudo /etc/init.d/mythtv-backend restart", and looking at the process list (ps -A u | grep myth), I see that the backend is indeed running under the "mythtv" user, and not under my own login. And when I look in /var/lib/mythtv/recordings, I see a handful of 0-byte MPG files owned by mythtv. Mythtv also owns the directory, which has 775 (drwxrwsr-x) permissions.
What gives? I was using MythTV 8.10 on here before, and while I had a number of serious problems preventing me from using it (I replaced the motherboard and installed 9.04 from scratch), I never encountered anything like this.
Starting up as the master server.
2009-06-19 22:58:34.931 HDHRChan(ffffffff/0): device found at address 192.168.1.11
2009-06-19 22:58:34.936 New DB connection, total: 3
2009-06-19 22:58:34.942 Connected to database 'mythconverg' at host: localhost
2009-06-19 22:58:35.027 New DB scheduler connection
2009-06-19 22:58:35.028 Connected to database 'mythconverg' at host: localhost
2009-06-19 22:58:35.035 MediaServer:: Loopback address specified - 127.0.0.1. Disabling UPnP
2009-06-19 22:58:35.036 Main::Registering HttpStatus Extension
2009-06-19 22:58:35.044 mythbackend version: 0.21.20080304-1 www.mythtv.org
2009-06-19 22:58:35.050 Enabled verbose msgs: important general
2009-06-19 22:58:35.059 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2009-06-19 22:58:38.031 Reschedule requested for id -1.
2009-06-19 22:58:38.044 Scheduled 0 items in 0.0 = 0.01 match + 0.01 place
2009-06-19 22:58:38.047 Seem to be woken up by USER
2009-06-19 22:58:55.031 Expiring 0 MBytes for 2080 @ Fri Jun 19 20:59:53 2009 => Unknown
2009-06-19 22:58:55.036 Expiring 0 MBytes for 2080 @ Fri Jun 19 20:59:56 2009 => Unknown
2009-06-19 22:58:55.038 Expiring 0 MBytes for 2080 @ Fri Jun 19 21:00:07 2009 => Unknown
2009-06-19 22:58:55.042 Expiring 0 MBytes for 2080 @ Fri Jun 19 21:00:09 2009 => Unknown
2009-06-19 22:58:58.045 Error deleting '/var/lib/mythtv/recordings/2080_20090619205953.mpg' could not open
eno: Permission denied (13)
2009-06-19 22:58:58.049 Delete Error '/var/lib/mythtv/recordings/2080_20090619205953.mpg'
eno: Permission denied (13)
2009-06-19 22:58:58.050 Error deleting file: /var/lib/mythtv/recordings/2080_20090619205953.mpg. Keeping metadata in database.
2009-06-19 22:58:58.054 Error deleting '/var/lib/mythtv/recordings/2080_20090619205956.mpg' could not open
eno: Permission denied (13)
2009-06-19 22:58:58.059 Delete Error '/var/lib/mythtv/recordings/2080_20090619205956.mpg'
eno: Permission denied (13)
2009-06-19 22:58:58.062 Error deleting file: /var/lib/mythtv/recordings/2080_20090619205956.mpg. Keeping metadata in database.
2009-06-19 22:58:58.070 Error deleting '/var/lib/mythtv/recordings/2080_20090619210007.mpg' could not open
eno: Permission denied (13)
2009-06-19 22:58:58.075 Delete Error '/var/lib/mythtv/recordings/2080_20090619210007.mpg'
eno: Permission denied (13)
2009-06-19 22:58:58.079 Error deleting file: /var/lib/mythtv/recordings/2080_20090619210007.mpg. Keeping metadata in database.
2009-06-19 22:58:58.086 Error deleting '/var/lib/mythtv/recordings/2080_20090619210009.mpg' could not open
eno: Permission denied (13)
2009-06-19 22:58:58.091 Delete Error '/var/lib/mythtv/recordings/2080_20090619210009.mpg'
eno: Permission denied (13)
2009-06-19 22:58:58.094 Error deleting file: /var/lib/mythtv/recordings/2080_20090619210009.mpg. Keeping metadata in database.
2009-06-19 22:59:30.225 MainServer::HandleAnnounce Monitor
2009-06-19 22:59:30.227 adding: HTPC as a client (events: 0)
2009-06-19 22:59:30.228 MainServer::HandleAnnounce Monitor
2009-06-19 22:59:30.228 adding: HTPC as a client (events: 1)
2009-06-19 22:59:30.238 MainServer::HandleAnnounce Playback
2009-06-19 22:59:30.267 adding: HTPC as a client (events: 0)
2009-06-19 22:59:30.317 TVRec(1): Changing from None to WatchingLiveTV
2009-06-19 22:59:30.320 TVRec(1): HW Tuner: 1->1
2009-06-19 22:59:31.371 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 15 min
2009-06-19 22:59:32.492 Finished recording Unknown: channel 2080
2009-06-19 22:59:33.514 Finished recording Unknown: channel 2080
2009-06-19 22:59:33.535 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 15 min
2009-06-19 22:59:33.578 Using runtime prefix = /usr
2009-06-19 22:59:33.583 Empty LocalHostName.
2009-06-19 22:59:33.584 Using localhost value of HTPC
2009-06-19 22:59:33.588 New DB connection, total: 1
2009-06-19 22:59:33.592 Connected to database 'mythconverg' at host: localhost
2009-06-19 22:59:33.593 Closing DB connection named 'DBManager0'
2009-06-19 22:59:33.595 Connected to database 'mythconverg' at host: localhost
2009-06-19 22:59:33.601 New DB connection, total: 2
2009-06-19 22:59:33.605 Connected to database 'mythconverg' at host: localhost
2009-06-19 22:59:33.646 Current Schema Version: 1214
2009-06-19 22:59:33.650 Preview Error: Previewer file '/var/lib/mythtv/recordings/2080_20090619225930.mpg' is not valid.
2009-06-19 22:59:33.670 Preview Error: Run() file not local: '/var/lib/mythtv/recordings/2080_20090619225930.mpg'
2009-06-19 22:59:33.677 Preview Error: Preview process not ok.
fileinfo(/var/lib/mythtv/recordings/2080_20090619225930.mpg.png) exists: 0 readable: 0 size: 0
2009-06-19 22:59:40.048 TVRec(1): Changing from WatchingLiveTV to None
2009-06-19 22:59:41.044 Finished recording Unknown: channel 2080
2009-06-19 22:59:55.044 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2009-06-19 23:00:55.053 Expiring 0 MBytes for 2080 @ Fri Jun 19 20:59:53 2009 => Unknown
2009-06-19 23:00:55.054 Expiring 0 MBytes for 2080 @ Fri Jun 19 20:59:56 2009 => Unknown
2009-06-19 23:00:55.057 Expiring 0 MBytes for 2080 @ Fri Jun 19 21:00:07 2009 => Unknown
2009-06-19 23:00:55.059 Expiring 0 MBytes for 2080 @ Fri Jun 19 21:00:09 2009 => Unknown
2009-06-19 23:00:58.060 Error deleting '/var/lib/mythtv/recordings/2080_20090619205953.mpg' could not open
eno: Permission denied (13)
2009-06-19 23:00:58.064 Delete Error '/var/lib/mythtv/recordings/2080_20090619205953.mpg'
eno: Permission denied (13)
2009-06-19 23:00:58.077 Error deleting file: /var/lib/mythtv/recordings/2080_20090619205953.mpg. Keeping metadata in database.
2009-06-19 23:00:58.082 Error deleting '/var/lib/mythtv/recordings/2080_20090619205956.mpg' could not open
eno: Permission denied (13)
2009-06-19 23:00:58.086 Delete Error '/var/lib/mythtv/recordings/2080_20090619205956.mpg'
eno: Permission denied (13)
2009-06-19 23:00:58.095 Error deleting file: /var/lib/mythtv/recordings/2080_20090619205956.mpg. Keeping metadata in database.
2009-06-19 23:00:58.102 Error deleting '/var/lib/mythtv/recordings/2080_20090619210007.mpg' could not open
eno: Permission denied (13)
2009-06-19 23:00:58.107 Delete Error '/var/lib/mythtv/recordings/2080_20090619210007.mpg'
eno: Permission denied (13)
2009-06-19 23:00:58.114 Error deleting file: /var/lib/mythtv/recordings/2080_20090619210007.mpg. Keeping metadata in database.
2009-06-19 23:00:58.126 Error deleting '/var/lib/mythtv/recordings/2080_20090619210009.mpg' could not open
eno: Permission denied (13)
2009-06-19 23:00:58.136 Delete Error '/var/lib/mythtv/recordings/2080_20090619210009.mpg'
eno: Permission denied (13)
2009-06-19 23:00:58.145 Error deleting file: /var/lib/mythtv/recordings/2080_20090619210009.mpg. Keeping metadata in database.
2009-06-19 23:01:10.231 HDHRChan(ffffffff/0): device found at address 192.168.1.11