[ERROR] Unhandled exception caught from main program.

d00zah · #1

Only night when a recording is active during update task run.

'Portable package for Win7' extracted to custom location... no installer.

Only error encountered since update... ~ 8/13.

Subsequent manual run (after recording completed) succeeded without error.

-

Code: Select all

Windows 7 x64 Application Log events:

Application: epg123Client.exe
Framework Version: v4.0.30319
Description: The process was terminated due to an unhandled exception.
Exception Info: System.NullReferenceException
   at epg123.Program.programRecording()
   at epg123.Program.Main(System.String[])

- System 

  - Provider 

   [ Name]  .NET Runtime 
 
  - EventID 1026 

   [ Qualifiers]  0 
 
   Level 2 
 
   Task 0 
 
   Keywords 0x80000000000000 
 
  - TimeCreated 

   [ SystemTime]  2018-08-19T07:38:38.000000000Z 
 
   EventRecordID 93113 
 
   Channel Application 
 
   Computer M-MPC1 
 
   Security 
 

- EventData 

   Application: epg123Client.exe Framework Version: v4.0.30319 Description: The process was terminated due to an unhandled exception. Exception Info: System.NullReferenceException at epg123.Program.programRecording() at epg123.Program.Main(System.String[])  

   
Faulting application name: epg123Client.exe, version: 1.2.4.0, time stamp: 0x5b6f26e3
Faulting module name: unknown, version: 0.0.0.0, time stamp: 0x00000000
Exception code: 0xc0000005
Fault offset: 0x000007fe8b0c5360
Faulting process id: 0x1fa0
Faulting application start time: 0x01d4378fa3b9ea97
Faulting application path: D:\epg123\epg123Client.exe
Faulting module path: unknown

- System 

  - Provider 

   [ Name]  Application Error 
 
  - EventID 1000 

   [ Qualifiers]  0 
 
   Level 2 
 
   Task 100 
 
   Keywords 0x80000000000000 
 
  - TimeCreated 

   [ SystemTime]  2018-08-19T07:38:41.000000000Z 
 
   EventRecordID 93114 
 
   Channel Application 
 
   Computer M-MPC1 
 
   Security 
 

- EventData 

   epg123Client.exe 
   1.2.4.0 
   5b6f26e3 
   unknown 
   0.0.0.0 
   00000000 
   c0000005 
   000007fe8b0c5360 
   1fa0 
   01d4378fa3b9ea97 
   D:\epg123\epg123Client.exe 
   unknown 
   e3f76927-a382-11e8-8860-e06995ddf04f 

   
epg123 tracelog:

[8/19/2018 3:30:03 AM] ===============================================================================
[8/19/2018 3:30:03 AM]  Beginning epg123 update execution. version 1.2.4.0
[8/19/2018 3:30:03 AM] ===============================================================================
[8/19/2018 3:30:03 AM] [ INFO] Beginning EPG123 update execution. 2018-08-19 07:30:03Z
[8/19/2018 3:30:03 AM] [ INFO] DaysToDownload: 21 , TheTVDBNumbers : True , PrefixEpisodeTitle: False , PrefixEpisodeDescription : False , AppendEpisodeDesc: True , OADOverride : True , TMDbCoverArt: True , IncludeSDLogos : True , AutoAddNew: True , CreateXmltv: False , ModernMediaUiPlusSupport: False
[8/19/2018 3:30:04 AM] [ INFO] Token request successful. serverID: 20141201.web.X
[8/19/2018 3:30:04 AM] [ INFO] Status request successful. account expires: 2019-07-10T15:24:40Z , lineups: 1/4 , lastDataUpdate: 2018-08-19T05:04:01Z
[8/19/2018 3:30:04 AM] [ INFO] system status: Online , message: No known issues.
[8/19/2018 3:30:05 AM] [ INFO] Successfully retrieved TMDb configurations.
[8/19/2018 3:30:05 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[8/19/2018 3:30:05 AM] Entering buildLineupServices() for 1 lineups.
[8/19/2018 3:30:05 AM] [ INFO] Successfully retrieved the station mapping for lineup ***************.
[8/19/2018 3:30:06 AM] Exiting buildLineupServices(). SUCCESS.
[8/19/2018 3:30:06 AM] Entering getAllScheduleEntryMd5s() for 21 days on 146 stations.
[8/19/2018 3:30:07 AM] [ INFO] Successfully retrieved Md5s for 146 station's daily schedules.
[8/19/2018 3:30:40 AM] [ INFO] Successfully retrieved 146 station's daily schedules.
[8/19/2018 3:30:53 AM] [ INFO] Found 1978 cached daily schedules.
[8/19/2018 3:30:53 AM] [ INFO] Downloaded 1075 daily schedules.
[8/19/2018 3:31:54 AM] [ INFO] Processed 3053 daily schedules for 146 stations.
[8/19/2018 3:31:54 AM] Exiting getAllScheduleEntryMd5s(). SUCCESS.
[8/19/2018 3:31:54 AM] Entering buildAllProgramEntries() for 27450 programs.
[8/19/2018 3:37:37 AM] [ INFO] Found 24916 cached program descriptions.
[8/19/2018 3:37:39 AM] [ INFO] Successfully retrieved 2534 program descriptions.
[8/19/2018 3:37:52 AM] [ INFO] Processed 27450 program descriptions.
[8/19/2018 3:37:52 AM] Exiting buildAllProgramEntries(). SUCCESS.
[8/19/2018 3:37:52 AM] Entering buildAllGenericSeriesInfoDescriptions() for 3194 series.
[8/19/2018 3:38:22 AM] [ INFO] Found 3068 cached series descriptions.
[8/19/2018 3:38:22 AM] [ INFO] Successfully retrieved 126 generic program descriptions.
[8/19/2018 3:38:22 AM] [ INFO] Processed 3194 series descriptions.
[8/19/2018 3:38:22 AM] Exiting buildAllGenericSeriesInfoDescriptions(). SUCCESS.
[8/19/2018 3:38:22 AM] Entering getAllMoviePosters() for 973 movies.
[8/19/2018 3:38:22 AM] [ INFO] Found 926 cached movie poster links.
[8/19/2018 3:38:23 AM] [ INFO] Successfully retrieved artwork info for 47 programs.
[8/19/2018 3:38:23 AM] [ INFO] TMDb catalog search for "Blind Revenge" from 2009 found 1 results.
[8/19/2018 3:38:23 AM] [ INFO] TMDb catalog search for "In the Heat of the Night: Give Me Your Life" from 1994 found 0 results.
[8/19/2018 3:38:23 AM] [ INFO] TMDb catalog search for "In the Heat of the Night: Give Me Your Life" from 1993 found 0 results.
[8/19/2018 3:38:23 AM] [ INFO] TMDb catalog search for "In the Heat of the Night: Give Me Your Life" from 1995 found 0 results.
[8/19/2018 3:38:23 AM] [ INFO] Processed 973 movie poster links.
[8/19/2018 3:38:23 AM] Exiting getAllMoviePosters(). SUCCESS.
[8/19/2018 3:38:23 AM] Entering getAllSeriesImages() for 3194 series.
[8/19/2018 3:38:23 AM] [ INFO] Found 2975 cached series image links.
[8/19/2018 3:38:23 AM] [ INFO] Successfully retrieved artwork info for 219 programs.
[8/19/2018 3:38:24 AM] [ INFO] Processed 3194 series image links.
[8/19/2018 3:38:24 AM] Exiting getAllSeriesImages(). SUCCESS.
[8/19/2018 3:38:24 AM] [ INFO] Completed compiling keywords and keyword groups.
[8/19/2018 3:38:25 AM] [ INFO] Completed save of the MXF file to "D:\epg123\output\epg123.mxf".
[8/19/2018 3:38:25 AM] [ INFO] Completed save of image archive file to "D:\epg123\guideImages.xml".
[8/19/2018 3:38:36 AM] [ INFO] 2676 files deleted from the cache directory during cleanup.
[8/19/2018 3:38:36 AM] [ INFO] Generated .mxf file contains 146 services, 3194 series, 27450 programs, and 40468 people with 4258 image links.
[8/19/2018 3:38:36 AM] [ INFO] Completed EPG123 update execution. SUCCESS.
[8/19/2018 3:38:36 AM] [ INFO] epg123 update execution time was 00:08:32.7060000.
[8/19/2018 3:38:36 AM] ===============================================================================
[8/19/2018 3:38:36 AM]  Beginning epg123 client execution. version 1.2.4.0
[8/19/2018 3:38:36 AM] ===============================================================================
[8/19/2018 3:38:36 AM] [ INFO] Beginning epg123 client execution. 2018-08-19 07:38:36Z
[8/19/2018 3:38:36 AM] [ INFO] Import: True , Match: False , NoLogo: False , Force: False , ShowProgress: False
[8/19/2018 3:38:36 AM] [ INFO] epg123 client version: 1.2.4.0
[8/19/2018 3:38:37 AM] [ERROR] Unhandled exception caught from main program. message: Object reference not set to an instance of an object.

d00zah · #2

Tried to manually repro when next scheduled recording kicked off... no error? Delayed import tray icon present.

Scheduled update task related?

Code: Select all

[8/19/2018 10:13:11 AM] ===============================================================================
[8/19/2018 10:13:11 AM]  Activating the epg123 configuration GUI. version 1.2.4.0
[8/19/2018 10:13:11 AM] ===============================================================================
[8/19/2018 10:13:12 AM] [ INFO] Successfully queried the Task Scheduler for status. Could not start. Last Run 8/19/2018 3:29:59 AM; Exit: 0xC0000005
[8/19/2018 10:13:12 AM] [ INFO] Token request successful. serverID: 20141201.web.X
[8/19/2018 10:13:13 AM] [ INFO] Status request successful. account expires: 2019-07-10T15:24:40Z , lineups: 1/4 , lastDataUpdate: 2018-08-19T05:04:01Z
[8/19/2018 10:13:13 AM] [ INFO] system status: Online , message: No known issues.
[8/19/2018 10:13:13 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[8/19/2018 10:13:13 AM] [ INFO] Successfully retrieved the station mapping for lineup ***************.
[8/19/2018 10:13:15 AM] ===============================================================================
[8/19/2018 10:13:15 AM]  Beginning epg123 update execution. version 1.2.4.0
[8/19/2018 10:13:15 AM] ===============================================================================
[8/19/2018 10:13:15 AM] [ INFO] Beginning EPG123 update execution. 2018-08-19 14:13:15Z
[8/19/2018 10:13:15 AM] [ INFO] DaysToDownload: 21 , TheTVDBNumbers : True , PrefixEpisodeTitle: False , PrefixEpisodeDescription : False , AppendEpisodeDesc: True , OADOverride : True , TMDbCoverArt: True , IncludeSDLogos : True , AutoAddNew: True , CreateXmltv: False , ModernMediaUiPlusSupport: False
[8/19/2018 10:13:15 AM] [ INFO] Status request successful. account expires: 2019-07-10T15:24:40Z , lineups: 1/4 , lastDataUpdate: 2018-08-19T05:04:01Z
[8/19/2018 10:13:15 AM] [ INFO] system status: Online , message: No known issues.
[8/19/2018 10:13:15 AM] [ INFO] Successfully retrieved TMDb configurations.
[8/19/2018 10:13:15 AM] [ INFO] Successfully requested listing of client lineups from Schedules Direct.
[8/19/2018 10:13:15 AM] Entering buildLineupServices() for 1 lineups.
[8/19/2018 10:13:15 AM] [ INFO] Successfully retrieved the station mapping for lineup USA-MA54265-X.
[8/19/2018 10:13:16 AM] Exiting buildLineupServices(). SUCCESS.
[8/19/2018 10:13:16 AM] Entering getAllScheduleEntryMd5s() for 21 days on 146 stations.
[8/19/2018 10:13:17 AM] [ INFO] Successfully retrieved Md5s for 146 station's daily schedules.
[8/19/2018 10:13:18 AM] [ INFO] Found 3053 cached daily schedules.
[8/19/2018 10:13:18 AM] [ INFO] Downloaded 0 daily schedules.
[8/19/2018 10:13:21 AM] [ INFO] Processed 3053 daily schedules for 146 stations.
[8/19/2018 10:13:21 AM] Exiting getAllScheduleEntryMd5s(). SUCCESS.
[8/19/2018 10:13:21 AM] Entering buildAllProgramEntries() for 27450 programs.
[8/19/2018 10:13:41 AM] [ INFO] Found 27450 cached program descriptions.
[8/19/2018 10:13:41 AM] [ INFO] Processed 27450 program descriptions.
[8/19/2018 10:13:41 AM] Exiting buildAllProgramEntries(). SUCCESS.
[8/19/2018 10:13:41 AM] Entering buildAllGenericSeriesInfoDescriptions() for 3194 series.
[8/19/2018 10:13:44 AM] [ INFO] Found 3194 cached series descriptions.
[8/19/2018 10:13:44 AM] [ INFO] Processed 3194 series descriptions.
[8/19/2018 10:13:44 AM] Exiting buildAllGenericSeriesInfoDescriptions(). SUCCESS.
[8/19/2018 10:13:44 AM] Entering getAllMoviePosters() for 973 movies.
[8/19/2018 10:13:44 AM] [ INFO] Found 970 cached movie poster links.
[8/19/2018 10:13:44 AM] [ INFO] Successfully retrieved artwork info for 3 programs.
[8/19/2018 10:13:44 AM] [ INFO] Processed 973 movie poster links.
[8/19/2018 10:13:44 AM] Exiting getAllMoviePosters(). SUCCESS.
[8/19/2018 10:13:44 AM] Entering getAllSeriesImages() for 3194 series.
[8/19/2018 10:13:44 AM] [ INFO] Found 3083 cached series image links.
[8/19/2018 10:13:44 AM] [ INFO] Successfully retrieved artwork info for 111 programs.
[8/19/2018 10:13:45 AM] [ INFO] Processed 3194 series image links.
[8/19/2018 10:13:45 AM] Exiting getAllSeriesImages(). SUCCESS.
[8/19/2018 10:13:45 AM] [ INFO] Completed compiling keywords and keyword groups.
[8/19/2018 10:13:46 AM] [ INFO] Completed save of the MXF file to "D:\epg123\output\epg123.mxf".
[8/19/2018 10:13:46 AM] [ INFO] Completed save of image archive file to "D:\epg123\guideImages.xml".
[8/19/2018 10:13:47 AM] [ INFO] 0 files deleted from the cache directory during cleanup.
[8/19/2018 10:13:47 AM] [ INFO] Generated .mxf file contains 146 services, 3194 series, 27450 programs, and 40468 people with 4258 image links.
[8/19/2018 10:13:47 AM] [ INFO] Completed EPG123 update execution. SUCCESS.
[8/19/2018 10:13:48 AM] [ INFO] epg123 update execution time was 00:00:32.9388787.
[8/19/2018 10:13:48 AM] ===============================================================================
[8/19/2018 10:13:48 AM]  Beginning epg123 client execution. version 1.2.4.0
[8/19/2018 10:13:48 AM] ===============================================================================
[8/19/2018 10:13:48 AM] [ INFO] Beginning epg123 client execution. 2018-08-19 14:13:48Z
[8/19/2018 10:13:48 AM] [ INFO] Import: True , Match: False , NoLogo: False , Force: False , ShowProgress: True
[8/19/2018 10:13:48 AM] [ INFO] epg123 client version: 1.2.4.0
[8/19/2018 10:13:49 AM] [ INFO] Recording in progress: 10:00 AM - 11:00 AM
[8/19/2018 11:11:02 AM] Entering importMxfFile() for file "D:\epg123\output\epg123.mxf"
[8/19/2018 11:12:13 AM] [ INFO] Successfully imported .mxf file into Media Center database. Exit code: 0
[8/19/2018 11:12:13 AM] Exiting importMxfFile(). SUCCESS.
[8/19/2018 11:12:13 AM] [ INFO] Completed lineup refresh.
[8/19/2018 11:12:13 AM] Entering runWmcTask(ReindexSearchRoot)
[8/19/2018 11:12:13 AM] [ INFO] SUCCESS: Attempted to run the scheduled task "Microsoft\Windows\Media Center\ReindexSearchRoot".
[8/19/2018 11:12:13 AM] [ INFO] Successfully started the ReindexSearchRoot task. Exit code: 0
[8/19/2018 11:12:13 AM] Exiting runWmcTask(ReindexSearchRoot). SUCCESS.
[8/19/2018 11:12:13 AM] Entering runWmcTask(PvrScheduleTask)
[8/19/2018 11:12:13 AM] [ INFO] SUCCESS: Attempted to run the scheduled task "Microsoft\Windows\Media Center\PvrScheduleTask".
[8/19/2018 11:12:13 AM] [ INFO] Successfully started the PvrScheduleTask task. Exit code: 0
[8/19/2018 11:12:13 AM] Exiting runWmcTask(PvrScheduleTask). SUCCESS.
[8/19/2018 11:12:13 AM] [ INFO] Completed EPG123 client execution.
[8/19/2018 11:12:13 AM] [ INFO] EPG123 client execution time was 00:58:25.6167728.

#3

Well that's new. It looks like the null was experienced in reporting what was being recorded at the time. That "Recording in progress:" line should have contained the channel number, callsign, and program title along with episode if it existed. Even stranger is it still waited over an hour and then successfully imported the MXF file. Is there more information in the event log? Do you know what was recording at the time with start time and end time?

Code: Select all

[8/19/2018 10:13:49 AM] [ INFO] Recording in progress: 10:00 AM - 11:00 AM

Logger.WriteInformation(string.Format("Recording in progress: {0:hh:mm tt} - {1:hh:mm tt} on {2} {3} -> {4} - {5}",
                                       recording.ScheduleEntry.StartTime.ToLocalTime(),
                                       recording.ScheduleEntry.EndTime.ToLocalTime(),
                                       recording.Channel.ChannelNumber,
                                       recording.ScheduleEntry.Service.CallSign,
                                       recording.ScheduleEntry.Program.Title,
                                       recording.ScheduleEntry.Program.EpisodeTitle ?? string.Empty));

d00zah · #4

garyan2 wrote:Well that's new. It looks like the null was experienced in reporting what was being recorded at the time. That "Recording in progress:" line should have contained the channel number, callsign, and program title along with episode if it existed. Even stranger is it still waited over an hour and then successfully imported the MXF file. Is there more information in the event log? Do you know what was recording at the time with start time and end time?

It's there, just redacted. Scheduled recordings from guide work fine & accurately log channel number, callsign, and program title, etc..

The original failure was a 'Channel & Time', 12 hour (+ padding) block recording... from MC event log:

FNC Sat Evening Block started recording on 8/18/2018 6:58:03 PM and stopped on 8/19/2018 7:10:00 AM as scheduled.

I only have 3 of these, but this is the only one ever active during a scheduled update. 1st time it ever encountered an error.

#5

d00zah wrote:It's there, just redacted. Scheduled recordings from guide work fine.

The original failure was a 'Channel & Time', 12 hour (+ padding) block recording... from MC event log:

FNC Sat Evening Block started recording on 8/18/2018 6:58:03 PM and stopped on 8/19/2018 7:10:00 AM as scheduled.

I only have 3 of these, but this is the only one ever active during a scheduled update.

Ah, that explains the missing information. Also, with that information, I guess the log entries you posted were when you tried to recreate the error?

When does your task run? I ask because the import will wait for up to 5 hours. If a recording is still happening 5 hours after your scheduled update, then it will abort. There should have been a log entry "A program recording is still in progress after 5 hours. Aborting the mxf file import." It doesn't explain any unhandled exception though.

Can you post the trace.log contents for the original failure? I wonder if the problem is EPG123 can't maintain a running Event Log for that long.

d00zah · #6

garyan2 wrote:Ah, that explains the missing information. Also, with that information, I guess the log entries you posted were when you tried to recreate the error?

The 1st post is the actual log from the 3:30AM scheduled update task... SD schedule name redacted... complete, plus Application log error reports.

The manual repro log from the 2nd post is the actual log... SD schedule name & recording name redacted... complete

garyan2 wrote:When does your task run? I ask because the import will wait for up to 5 hours. If a recording is still happening 5 hours after your scheduled update, then it will abort. There should have been a log entry "A program recording is still in progress after 5 hours. Aborting the mxf file import." It doesn't explain any unhandled exception though.

Scheduled task runs nightly @ 3:30 AM.

Based on your description, I interpret the log of the failure to mean epg123 'blew up' attempting the 'epg123 client execution'. before it could schedule the delayed import... it never happened after the error.

The null reference error was probably a failure to read the 'channel number, callsign, and program title, etc.' from the active WMC 'Channel & Time', 12 hour (+ padding) block 'FNC Sat Evening Block' scheduled recording, which is independent from the guide.

garyan2 wrote:Can you post the trace.log contents for the original failure? I wonder if the problem is EPG123 can't maintain a running Event Log for that long.

Again, the 1st post is the actual log from the 3:30 AM scheduled update task... SD schedule name redacted... complete, plus Application log error reports.

I've PM'd you the complete, unredacted trace log for the last ~3 days.

#7

I am such a doofus. Sorry, I didn't scroll down far enough on the first post to see the trace.log entries. Everything is much clearer now.

I will see what I can do to recreate the problem here with a Channel&Time recording... there may be some peculiarities with my querying the recordings that I hadn't seen before in testing.

d00zah · #8

Just to restate... that recording & scheduled updates have been error free until the v1.2.3.0 - v1.2.4.0 releases.

#9

Well that was quick. First try, and I found it... that never happens. The client is choking on the callsign; the recording.ScheduleEntry.Service is null so it throws the exception.

I'll get this fixed and it will be in the next release.

None of this code has been touched in a verrrrry long time so is not specific to v1.2.4.0. This has been around since I added it but will only be an issue with Channel & Time recordings and I think only a percentage of those.

d00zah · #10

Hmm...... 1st I've seen of the exception since installing ep123. The only recent system change was the epg123 update????

Thanks again for your quick response & great work, Gary!

TheGreenButton - Windows Media Center Forums

TheGreenButton - Windows Media Center Forums

[ERROR] Unhandled exception caught from main program.

[ERROR] Unhandled exception caught from main program.

Re: [ERROR] Unhandled exception caught from main program.

Re: [ERROR] Unhandled exception caught from main program.

Re: [ERROR] Unhandled exception caught from main program.

Re: [ERROR] Unhandled exception caught from main program.

Re: [ERROR] Unhandled exception caught from main program.

Re: [ERROR] Unhandled exception caught from main program.

Re: [ERROR] Unhandled exception caught from main program.

Re: [ERROR] Unhandled exception caught from main program.

Re: [ERROR] Unhandled exception caught from main program.