timeout and invalid XML with fault tags

Forum rules
Get Help using the Schedules Direct service. NOTE: application issues are probably better resolved via the application's support methods. If you post here, at least include your application name!

timeout and invalid XML with fault tags

Postby faginbagin » Sun Mar 16, 2014 12:34 pm

I have been having a problem with automatic runs of mythfilldatabase for several weeks. It had been working for me for years, and was working for a few weeks after I upgraded from mythtv 0.23 to 0.27 on Jan 16, 2014. The last time I had a successful automatic run was Feb 21, 2014. It is now Mar 16, 2014. If I run the command from the command line, with the --dd-grab-all option, I get the data. Perhaps I can work around this with a cron job, but I think I should at least report the problem and provide you with any help I can to allow mythbackend/mythfilldatabase to do the job automatically. Perhaps my working with you will help other users. For example, my sister's mythtv system is having the same problem.

I'm pretty sure the problem is on the schedules direct side because these are the failure modes I've been seeing:

1) I believe mythfilldatabase is timing out when it doesn't receive data for over 60 seconds. Usually, mythfilldatabase logs an error over 60 seconds after logging that it is sending a request. For example:
Code: Select all
Mar 15 02:00:43 hostname mythfilldatabase: mythfilldatabase[21055]: I CoreContext datadirect.cpp:1017 (DDPost) Downloading DataDirect feed
Mar 15 02:02:20 hostname mythfilldatabase: mythfilldatabase[21055]: E CoreContext datadirect.cpp:1184 (GrabData) DataDirect: Failed to get data: Download error

Sometimes the error message is 3 minutes after the info message, but never less than 60 seconds. Last night, I managed to capture more verbose logs from mythfilldatabase and I can see mythfilldatabase is getting 10 bytes from schedules direct, and then it is timing out 60 seconds later. Here's an example of the more verbose logs:
Code: Select all
2014-03-16 02:05:37.325031 I [27161/27161] CoreContext datadirect.cpp:1017 (DDPost) - Downloading DataDirect feed
2014-03-16 02:05:37.385506 D [27161/27161] CoreContext mythdownloadmanager.cpp:641 (postAuth) - DownloadManager: postAuth('http://webservices.schedulesdirect.tmsdatadirect.com/schedulesdirect/tvlistings/xtvdService', '140734231938816')
2014-03-16 02:05:37.393753 D [27161/27168] DownloadManager mythdownloadmanager.cpp:707 (downloadQNetworkRequest) - Checking cache for http://webservices.schedulesdirect.tmsdatadirect.com/schedulesdirect/tvlistings/xtvdService
2014-03-16 02:05:38.248941 D [27161/27168] DownloadManager mythdownloadmanager.cpp:799 (authCallback) - Calling auth callback
2014-03-16 02:05:38.248952 D [27161/27168] DownloadManager datadirect.cpp:973 (authenticationCallback) - DataDirect auth callback
2014-03-16 02:05:55.256218 D [27161/27168] DownloadManager mythdownloadmanager.cpp:1260 (downloadProgress) - DownloadManager: downloadProgress(10, -1) (for reply 140507103678240)
2014-03-16 02:05:55.256240 D [27161/27168] DownloadManager mythdownloadmanager.cpp:1276 (downloadProgress) - DownloadManager: downloadProgress: http://webservices.schedulesdirect.tmsdatadirect.com/schedulesdirect/tvlistings/xtvdService to  is at 10 of -1 bytes downloaded
2014-03-16 02:06:55.416183 D [27161/27161] CoreContext mythdownloadmanager.cpp:852 (downloadNow) - DownloadManager: Aborting download - lack of data transfer
2014-03-16 02:06:55.416255 E [27161/27161] CoreContext datadirect.cpp:1184 (GrabData) - DataDirect: Failed to get data: Download error


2) Sometimes I get a reply that is incomplete and that contains invalid XML with <fault... tags. Here's a sample log:
Code: Select all
Mar 15 02:03:22 hostname mythfilldatabase: mythfilldatabase[21055]: I CoreContext datadirect.cpp:1017 (DDPost) Downloading DataDirect feed
Mar 15 02:04:48 hostname mythfilldatabase: mythfilldatabase[21055]: I CoreContext datadirect.cpp:1029 (DDPost) Downloaded 3993 bytes
Mar 15 02:04:48 hostname mythfilldatabase: mythfilldatabase[21055]: I CoreContext datadirect.cpp:1031 (DDPost) Uncompressing DataDirect feed
Mar 15 02:04:48 hostname mythfilldatabase: mythfilldatabase[21055]: I CoreContext datadirect.cpp:1036 (DDPost) Uncompressed to 23374 bytes
Mar 15 02:04:48 hostname mythfilldatabase: mythfilldatabase[21055]: I CoreContext mythdbcon.cpp:436 (getStaticCon) New static DB connectionDataDirectCon
Mar 15 02:04:48 hostname mythfilldatabase: mythfilldatabase[21055]: I CoreContext datadirect.cpp:463 (characters) DataDirect: Your subscription expires on Sat Nov 22 2014 3:24 pm
Mar 15 02:04:49 hostname mythfilldatabase: mythfilldatabase[21055]: I CoreContext datadirect.cpp:2318 (set_lineup_type) DataDirect: sourceid 2 has lineup type: CableDigital
Mar 15 02:04:49 hostname mythfilldatabase: mythfilldatabase[21055]: E CoreContext datadirect.cpp:1217 (GrabData) DataDirect: DataDirect XML failed to properly parse, downloaded listings were probably corrupt.
Mar 15 02:04:49 hostname mythfilldatabase: mythfilldatabase[21055]: E CoreContext filldata.cpp:237 (GrabDDData) Encountered error in grabbing data.

And here's the tail of the reply that caused the error:
Code: Select all
</lineup>
</lineups>
<schedules>
<SOAP-ENV:Fault>
<faultcode xmlns:ns1='urn:TMSWebServices'>ns1:ZTVWebServiceTechnicalError</faultcode>
<faultstring>An unexpected error has occurred. Please try again later. If this message reappears, please contact support.</faultstring>
<detail><faultnumber>100</faultnumber></detail>
</SOAP-ENV:Fault>
</SOAP-ENV:Body>
</SOAP-ENV:Envelope>

As you can see, schedules direct is trying to report a problem to mythfilldatabase, but mythfilldatabase cannot interpret the XML because the <schedules> tag is not closed.

If you want complete log files and the complete reply I managed to salvage, I'll be happy to provide them, once I figure out how you prefer to receive them. Of course, if I can help with any other information or testing, don't hesitate to ask.

FWIW, I have put together a wget command that I believe is the same as the post request that mythfilldatabase sends to schedules direct. It worked when I tried it this afternoon. I will try to use it at the time of day when the automatic runs have been failing. I offer it here, in case it helps others:

Code: Select all
wget \
--header='Accept-Encoding: gzip' \
--header='Content-Type: application/soap+xml; charset=utf-8' \
--user-agent="MythTV v0.27.20140303-1 MythDownloadManager" \
--user=sched-direct-id \
--password=sched-direct-passwd \
--post-data="<?xml version='1.0' encoding='utf-8'?>
<SOAP-ENV:Envelope
xmlns:SOAP-ENV='http://schemas.xmlsoap.org/soap/envelope/'
xmlns:xsd='http://www.w3.org/2001/XMLSchema'
xmlns:xsi='http://www.w3.org/2001/XMLSchema-instance'
xmlns:SOAP-ENC='http://schemas.xmlsoap.org/soap/encoding/'>
<SOAP-ENV:Body>
<ns1:download  xmlns:ns1='urn:TMSWebServices'>
<startTime xsi:type='xsd:dateTime'>2014-03-17T00:00:00Z</startTime>
<endTime xsi:type='xsd:dateTime'>2014-03-18T00:00:00Z</endTime>
</ns1:download>
</SOAP-ENV:Body>
</SOAP-ENV:Envelope>" \
'http://webservices.schedulesdirect.tmsdatadirect.com/schedulesdirect/tvlistings/xtvdService' \
-O - | gunzip > reply


Be sure to change sched-direct-id and sched-direct-passwd to your schedules direct userid and password.

TIA,
Helen
faginbagin
 
Posts: 8
Joined: Sun Mar 16, 2014 11:22 am

Re: timeout and invalid XML with fault tags

Postby rmeden » Wed Mar 19, 2014 6:13 pm

This points to a problem on Tribune's servers. I'm surprised get-all works, normally adding more days makes it worse. If the problem is repeatable, email support and we can submit the issue to Tribune.

Robert
rmeden
SD Board Member
 
Posts: 1511
Joined: Tue Aug 14, 2007 2:31 pm
Location: Cedar Hill, TX

Re: timeout and invalid XML with fault tags

Postby faginbagin » Wed Mar 19, 2014 10:02 pm

New data point: It's not a grab one day vs grab two weeks problem. I ran "mythfilldatabase --dd-grab-all" on my sister's myth system. I started it around 2:40 am EDT and it times out around 3 am. I suspect data was being downloaded in dribs and drabs until nothing was sent for at least 60 seconds, when mythfilldatabase timed out. I think it's more likely a time of day issue and my sister and I have been unfortunate enough to have been stuck at a bad time of day for several weeks. I just tried the same command tonight on her system and it succeeded, but the download speed seemed pretty slow to me. It took 4 min 29 secs to download 6474015 bytes. That's a download speed of 24067 bytes/sec.

So, how do I go about emailing support. I've combed the web site and the stickies for this support forum and the only thing that comes close is the "Report a Lineup Problem" form on the web site. Is that the mechanism? Or is there an email address, like support@schedulesdirect.org?

Regards,
Helen
faginbagin
 
Posts: 8
Joined: Sun Mar 16, 2014 11:22 am

Re: timeout and invalid XML with fault tags

Postby rmeden » Sat Mar 22, 2014 9:23 pm

left hand navigation column... 6th one down... "Contact Us" :)

If you can capture the bad XML and/or the XML error message, that would be great.

Robert
rmeden
SD Board Member
 
Posts: 1511
Joined: Tue Aug 14, 2007 2:31 pm
Location: Cedar Hill, TX

Re: timeout and invalid XML with fault tags

Postby faginbagin » Wed Mar 26, 2014 1:06 pm

Here's a copy of the message I sent using the "Contact Us" form:

I have been having a problem with automatic runs of mythfilldatabase for several weeks. It had been working for me for years, and was working for a few weeks after I upgraded from mythtv 0.23 to 0.27 on Jan 16, 2014. The last time I had a successful automatic run was Feb 21, 2014. It is now Mar 26, 2014. Sometimes, if I run the command from the command line, with the --dd-grab-all option, I get the data. Perhaps I can work around this with a cron job, but I think I should at least report the problem and provide you with any help I can to allow mythbackend/mythfilldatabase to do the job automatically. Perhaps my working with you will help other users. For example, my sister's mythtv system is having the same problem.

I think the primary problem is that mythfilldatabae is timing out after it receives no reply from schedules direct for over 60 seconds. And the timeouts may depend on the time of day. Schedules direct is instructing mythtv to use next grab times that are typically a few minutes after: 2 am, 9 pm (before DST changed) or 10 pm (after DST changed), Eastern Time. When I have been able to run the command successfully, it has been at different times of day than these. Here are dates/times when timeouts have occured:
2014-02-13 21:03:17
2014-02-15 21:03:20
2014-02-17 02:13:44
2014-02-18 21:03:40
2014-02-20 02:37:51
2014-02-22 21:02:13
2014-02-24 21:02:56
2014-02-26 21:02:28
2014-02-28 21:01:19
2014-03-02 21:02:09
2014-03-04 21:02:33
2014-03-06 02:02:38
2014-03-07 02:01:54
2014-03-08 21:02:14
2014-03-11 22:01:41
2014-03-13 22:01:52
2014-03-15 02:02:20
2014-03-16 02:06:55
2014-03-17 22:02:11
2014-03-19 22:01:56
2014-03-21 02:03:02
2014-03-22 22:02:51
2014-03-24 22:02:38

I have also had a few instances where mythfilldatabase reports: "DataDirect XML failed to properly parse, downloaded listings were probably corrupt". I have managed to grab the data from a couple instances of this error and found they do indeed contain invalid XML, due to either an open <schedules> or <programs> tag followed by these lines:
<SOAP-ENV:Fault>
<faultcode xmlns:ns1='urn:TMSWebServices'>ns1:ZTVWebServiceTechnicalError</faultcode>
<faultstring>An unexpected error has occurred. Please try again later. If this message reappears, please contact support.</faultstring>
<detail><faultnumber>100</faultnumber></detail>
</SOAP-ENV:Fault>
</SOAP-ENV:Body>
</SOAP-ENV:Envelope>

These types of errors have occurred at these dates/times:
2014-02-15 21:06:40
2014-02-18 21:01:40
2014-02-24 21:03:54
2014-02-26 21:06:40
2014-03-06 02:04:54
2014-03-15 02:04:49
2014-03-16 02:13:06
2014-03-16 16:12:36
2014-03-21 02:01:53
2014-03-22 22:01:50

I'd be happy to provide complete files for two separate occurrences.

I am adding this message to the following forum thread so the information is available to anyone suffering the same issues:
viewtopic.php?f=5&t=2541

Please let me know if I can provide more information.

Regards,
Helen Buus
faginbagin
 
Posts: 8
Joined: Sun Mar 16, 2014 11:22 am

Re: timeout and invalid XML with fault tags

Postby rmeden » Wed Mar 26, 2014 5:03 pm

We don't actually host the data, it comes direct from Tribune.

It sounds like Tribune's server is having a problem, the download thread is dying and the XML isn't being properly closed.

In addition, our system checks are also reporting a lot more failures than normal.

I'll ask them what's going on.

Robert
(I got your support email too, but I'll just keep things in here)
rmeden
SD Board Member
 
Posts: 1511
Joined: Tue Aug 14, 2007 2:31 pm
Location: Cedar Hill, TX

Re: timeout and invalid XML with fault tags

Postby faginbagin » Fri Mar 28, 2014 12:21 am

Thanks. Let me know if you would like the invalid XML files and how best to provide them. They are 23374 and 416462 bytes in length.

Regards,
Helen
faginbagin
 
Posts: 8
Joined: Sun Mar 16, 2014 11:22 am

Re: timeout and invalid XML with fault tags

Postby QBobWatson » Sat Mar 29, 2014 5:24 am

I'm having the same problem. When run automatically by mythbackend, mythfilldatabase always fails to grab any new listings, or at least it has failed every time since February. When run on the command line (with or without --dd-grab-all) it always succeeds. My mythbackend.log and /tmp/mythtv_ddp_data look exactly like faginbagin's. I'm running a recent mythbuntu version (2:0.27.0+fixes.20140324.8ee257c-0ubuntu0mythbuntu2).

Any update on what's going on?
QBobWatson
 
Posts: 1
Joined: Fri Mar 28, 2014 6:09 am

Re: timeout and invalid XML with fault tags

Postby fphillips » Tue May 13, 2014 1:11 pm

This MythTV bug affects users who have:
1. MythTV 0.27
2. Have MythFillGrabberSuggestsTime=True
3. Have a narrow RunWindow set. This is typically those who originally installed preceding the 0.25 release. Starting in 0.25, installs defaulted to an infinite run window (0-23).

I created a report
health.txt
(5.13 KiB) Downloaded 313 times
from my mythfilldatabase logs with the following script:
Code: Select all
#!/bin/bash

cat << EOF >/tmp/health

completed runs          download errors
*partial/corrupt
================        ================

EOF

cd /var/log/mythtv
grep "Downloaded" mythfilldatabase.201*|awk -F":" '{print $2":"$3}' >/tmp/completed
grep "corrupt" mythfilldatabase.201*|awk -F":" '{print $2":"$3}' >/tmp/partial
grep "Download error" mythfilldatabase.201*|awk -F":" '{print $2":"$3}' >/tmp/dl_error

cd /tmp
sed -i 's/^/\t\t\t\t\t/' dl_error
paste -sd '\n' completed dl_error |sort >> health
cat partial


You can see that the failures start in late January at 20:00 (21:00 once DST started), with the last successful run at that time Feb9, and a partial Mar11. I'm in CST, so that is 0200 UTC.

My theory is that the upgrade to 0.27, introducing #12101, caused the above users to start requesting at 0200 UTC, stuffing up the servers and causing download failures.

https://code.mythtv.org/trac/ticket/12101
http://www.mythtv.org/pipermail/mythtv- ... 61051.html
http://www.mythtv.org/pipermail/mythtv- ... 62209.html
fphillips
 
Posts: 12
Joined: Tue May 13, 2014 12:16 pm
Location: Austin. TX


Return to Support

Who is online

Users browsing this forum: No registered users and 7 guests

cron