InfiniTV 6 ETH Comments/Issues

#1

I just wanted to share some initial experiences getting up and running with the InfiniTV Eth 6 with Comast. I was new to Comcast cable (and cable in general) and Ceton. There is a very real danger of this becoming a rant so I will simmer down the complaints to one sentence:

It took exactly three weeks (3 technician visits, ~8 hours of phone calls/live chats, ~100 driven miles, 2 CableCARDs & 2 InfiniTV ETH) to get "working" cable TV.

Some background: Prior to this there was a single Comcast line coming into my house (from a telephone pole), connected directly to my modem. Great internet speeds (pay for 50mbit, typically get >50mbit).

CableCARD 1 (without gold strip) & InfiniTV ETH 1:
- Ceton Diagnostics reports CableCARD not detected, once every few minutes.
- ~66% of channels missing. Missing channels interlaced throughout the spectrum. (for example 13 & 16 have 37/3.5 SNR/SL, channel 15 has 12/-44 SNR/SL).

CableCARD 2 (with gold strip) & InfiniTV ETH 1:
- Ceton Diagnostics reports CableCARD not detected, once every few hours.
- ~66% of channels missing still.

Comcast Tech Visit 3: New Tech, Ramon, takes all of 60 seconds to realise that something outside of the house is blocking my signal. Turns out there is an analog era filter on the Comcast line down the road (to prevent my residence from getting premium analog channels, apparently).

CableCARD 2 & InfiniTV ETH 2:
- Everything working! (or is it?).

NB. Both the InfiniTV ETHs shipped with Firmware 6590. The first InfiniTV I upgraded immediately. With the second I decided to try out the shipped firmware. For Comcast reasons it was impossible for me to pair the Ceton/CableCARD that day (but I tried playing channels in WMC anyway). That evening I connected to the InfiniTV web interface and found all of the tuners in a status other than stopped (probably "PLAYING" but I don't remember) showing Channel 0, and the tuner temperature was 70.3 °C! I immediately unplugged the tuner and in the morning I upgraded to 7359 beta.

I have two HTPCs:
InfiniTV -> ZyXEL GS1100-16 -> Windows 8.1 HTPC
InfiniTV -> ZyXEL GS1100-16 -> ZyXEL GS1100-16 -> ASUS GX1005B (budget FAR 100mbit switch) - > Windows 8 HTPC

The small tests of the Windows 8 HTPC have worked without any issues.

Extended viewing on the Windows 8.1 HTPC has revealed some problems:

At least once since Tuesday the CableCARD has been lost and WMC has prompted to setup the new CableCARD when it is re-detected. Could I have really received two bad CableCARDs? It's certainly well inserted. Could temperature have been a factor? I'm seeing temperatures around 63 °C when tuners are in use.

I also frequently get a "Viewing Conflict" error message. This can come up when I've been happily watching a channel for quite some time. This eventually "fixes" itself, but what this really means is I get assigned another tuner. For example, I started watching BBC America (channel 114, Signal Level: 10.2 dBmV, SNR 39.0 dB) about 45 minutes ago and I now have 5/6 tuners "PLAYING" that channel.

I will update this post as I obtain more diagnostic information, but insight into the problems would be appreciated. I have what I would consider a high quality wired network.

#2

My CableCARD dropped out again yesterday, followed by WMC asking me to setup my CableCARD.

I would appreciate some guidance on whether this is most likely:
- My CableCARD (I've tried two)
- My Ceton InfiniTV ETH (I've tried two)
- High temperatures (low to mid 60s).

mdavej · #3

Mine does that when I let my computer sleep/wake. If I leave it on all the time, it never drops out. I blame Ceton or possibly WMC. I also guess it might be changing IP or DHCP lease running out on the ETH. Reserve an IP for it in your router and see if that helps.

Standing the box on end helps with temps as does a fan.

smassey22180 · #4

As a test you can lock 3 tuners to one WMC and 3 to the other. Tuner pooling was not working for my 2 WMCs. I don't need it anyway. May as well put a fan on the ETH 6. It can't hurt anything and some people think it runs faster when it is cooler.

#5

Thanks mdavej & smassey22180. I appreciate the input, it sounds like a fan is a no brainer.

I believe the CableCARD dropouts happen spontaneously (i.e. not associated with WMC waking up). I also think the CableCARD dropouts and the "Viewing Conflict" errors happens when my other WMC is powered-off.

Fortunately it is the weekend and so I can do some thorough debugging. I will experiment the influence of various factors on the behaviour of the Ceton and report back.

#6

I threw together a tool for monitoring the InfiniTV Eth so I could at least see what is happening when I get a viewing conflict error. I started running it tonight (with no fan) and waited for "Viewing Conflict"/"No Tuner Available" errors. Of course, since I started running the tool the InfiniTV has worked perfectly.

You can look at the output of the tool here (be patient, the images are dynamically generated): http://home.nxsfan.co.uk:8000/stats.py

For boolean states (Transport/CableCARD Status), anything <1 is False.

As of this moment it is recording 3 channels while playing a fourth. Within a couple of hours it should drop back down to one active tuner. Seeing as the temperature is still climbing while the InfiniTV is working perfectly, I'm thinking the problems I saw before were indeed temperature related.

#7

Here are the results of experiment 1: http://nxsfan.co.uk/ceton/experiment1.html
I personally find the results very interesting.

I'm conducting a second experiment where one channel is set to record for several hours, while 3 other channels have short term recordings.

JohnW248 · #8

It looks to me that your device is running way too hot. I think as soon as you hit 60 C that you're starting into a danger zone. My tuners run in the 48-55 C range depending on how many active tuners there are. Also you can have multiple tunes to the same channel number depending on the client request and the MC recording schedule. I'll often record a class movie on Tuner Classic Movies that has a short at the end and do a manual recording for the short as another request and two tuners will be in use at the same time to the same channel. If you have two computers being served by the tuner you could have multiple tuners going to the same channel.

But I noticed your "uk" address, are you using the device as a cableCARD tuner or not? If you are just using it as a clearQAM tuner there are other methods to simulate the cableCARD in the Ceton WebGui.

#9

Hi JohnW248. Just to recap, I'm using Comcast with a CableCARD. Did you have a look at the Experiment 1 link above? It demonstrates in high detail the conditions under which my setup fails (one htpc using multiple tuners).

Do you have the InfiniTV Eth? Is yours passively cooled? Is mine faulty because it hits such high temperatures? I got the impression that many InfiniTV Eths hit temperatures in the 60s?

I will test with a fan attached, but I would ideally like to understand the precise circumstances that induce a failure. I think it might be worth logging the jitter to my htpc (using iperf) from another device on the same switch, or the ping/rtt between my htpc and the InfiniTV, or maybe just the latency of the tuner property queries.

Here is the result of Experiment 2 (where I start 3 short recordings and one very long one): http://nxsfan.co.uk/ceton/experiment2.html
I can't seem to edit my old messages in this sub-forum.

JohnW248 · #10

: Ceton Tuner Temps

I did have a 6ETH but now have two 6T PCIe in two different machines. I do have three SD Primes. I have found that a little notebook cooler fan is ideal to set the tuners on. If you open the Ceton Diagnostic it will give you a pass/fail on tuner temp but only at the instant you check it. Your tuners seem to be running hot.

To fill in the variables, it would be helpful to know how this is all connected (switch/router/PC/extenders) and what kind of cableCARD you're using, obviously it is an "M" card but it could be either a Moto or Cisco device and then there is the FW (which you have no control over) on the CableCARD. Unfortunately the devices supplied by the cable company have a much wider range than the 3rd party tuning devices but two points you need to watch is the signal level (should be +/- 7 dBmV with 0 itdel) and your SNR which needs to be above 30 dB and preferably higher.

#11

Hey JohnW248.

I sat a 5v 12cm fan on the InfiniTV Eth 6 two hours ago and it hasn't gone above 51 C since. Shortly I will recreate Experiment 1 to see if it fixes the problem. I think I'm bombarding this thread with so much information that some details are getting lost in the noise. Here is the simple configuration I am trying to debug;

InfiniTV -> ZyXEL GS1100-16 -> Windows 8.1 HTPC (connected with two very short, known good, cat5e cables)
CableCARD: Motorola Version 1573 (gold strip on exterior)

If you have a look at Experiment 1 (or 2) you can see the signal level for all tuners during the course of the failure. My signal level varies between 0 and 12 dBmV (channel dependent), this is outside your +7 threshold, should I add a passive limiter? I'm sorry but I don't know what " 0 itdel" means. My SNR has been just under 40dB for all channels tested (for example 39.4 dB).

The Ceton Diagnostic Utility gave a "Pass" on temperatures even when they were in the high 60s.

JohnW248 · #12

"0 Itdel" should have read 0 dBmV is the IDEAL or PERFECT signal. Your high 12 dBmV should be brought down, maybe a 6 dB pad will help you and keep you within range, but also you should look at your SNR. All the elements in my chart can be found individually by going to the Ceton WebGui page (just open the IP address for the tuner) and click on the various tabs. There you can also open the tabs for the CableCARD information. I normally leave a tab open with the WebGui along with several other "checks" such as CA Stream, Diagnostics, etc (I have a Cisco card so there are differences where things are) along with the Tuning Adapter (I suspect you don't have SDV do deal with as well) and my chart.

You seem to have good signal and SNR, so with heat undercontrol the only other suspect would be the switch and the Ethernet drivers for the network card in your computer (can be a big issue). If you have any bandwidth issues you might go to CAT6 cables.

I just noticed this from your 1st experiment: ehrecv (WMC) reports an error on Tuners 1 & 4. I am unable to watch TV again.

If you get the ehrecv error, you can stop and restart the service (mc MUST BE CLOSED) and that should bring it back. The auto restart of the service won't always recover. When you get the ehrecv error you should do an immediate scan with the Ceton Diagnostic and save the file and then start a ticket, its important to have that scan right after you discover the issue. But that might be part of your problem, what's causing it is another mystery.

#13

JohnW248 wrote:All the elements in my chart can be found individually by going to the Ceton WebGui page (just open the IP address for the tuner) and click on the various tabs.

OK JohnW248. I'm feeling pretty dejected after reading this part of your message. Maybe there is another way for me to have logged the individual tuner temperatures, signal level, playstate, etc. but I have been polling it using the HTTP get_var cgi interface on the device itself. i.e. I'm aware of the web interface.

I'm not going to post Experiment 3 because it got a little messy from unintentional recordings, but the net behaviour was the same as before:

After several hours of viewing live TV, WMC reports a "Viewing Conflict". After 10/20 seconds or so it starts playing the channel again, however in the background it is assigned a different tuner, while the original tuner keeps "PLAYING" the channel. It keeps doing this until I eventually hit the "Tuner Not Available" message (amusingly this is before all the tuners are in use) and I need to restart the InfiniTV and my HTPC to get things working again. Right now (prior to restart) the InfiniTV tuner is working really hard using 5 tuners to stream channels to non-existent endpoints and I have to restart to watch TV again.

I also see occasional (daily?) "CableCARD Inserted" messages, with the Ceton Diagnostic Utility losing the CableCARD and then detecting it on the next refresh (curiously this isn't shown in the logs).

My network hardware is relatively high end. I frequently stream MUCH higher bitrate content over much larger portions of my network without any trouble. My HTPC network adapter is the AR8151. I see a lot of blame projected onto network hardware around here. Honestly, saying I should try CAT6 (to replace my CAT5e) sounds crazy!

Seriously though, I replaced the Ceton with my laptop, put my WMC machine in iperf server mode and ran some diagnostics:

Code: Select all

> iperf -c 192.168.1.114  -t 10 -i 2 -w 16m #(obviously 16m was a bit silly)
------------------------------------------------------------
Client connecting to 192.168.1.114, TCP port 5001
TCP window size:  129 KByte (WARNING: requested 16.0 MByte)
------------------------------------------------------------
[  4] local 192.168.1.129 port 50589 connected with 192.168.1.114 port 5001
[ ID] Interval       Transfer     Bandwidth
[  4]  0.0- 2.0 sec   221 MBytes   926 Mbits/sec
[  4]  2.0- 4.0 sec   224 MBytes   938 Mbits/sec
[  4]  4.0- 6.0 sec   224 MBytes   937 Mbits/sec
[  4]  6.0- 8.0 sec   224 MBytes   941 Mbits/sec
[  4]  8.0-10.0 sec   224 MBytes   937 Mbits/sec
[  4]  0.0-10.0 sec  1.09 GBytes   936 Mbits/sec

>iperf -c 192.168.1.114 -u -b 300m -t 10 -i 2 -w 16m # (I used 300m assuming 50mbit per channel (excessive!)).
------------------------------------------------------------
Client connecting to 192.168.1.114, UDP port 5001
Sending 1470 byte datagrams
UDP buffer size: 9.00 KByte (WARNING: requested 16.0 MByte)
------------------------------------------------------------
[  4] local 192.168.1.129 port 58714 connected with 192.168.1.114 port 5001
[ ID] Interval       Transfer     Bandwidth
[  4]  0.0- 2.0 sec  71.8 MBytes   301 Mbits/sec
[  4]  2.0- 4.0 sec  71.7 MBytes   301 Mbits/sec
[  4]  4.0- 6.0 sec  71.9 MBytes   301 Mbits/sec
[  4]  6.0- 8.0 sec  71.9 MBytes   301 Mbits/sec
[  4]  8.0-10.0 sec  71.6 MBytes   300 Mbits/sec
[  4]  0.0-10.0 sec   359 MBytes   301 Mbits/sec
[  4] Sent 256021 datagrams
[  4] Server Report:
[  4]  0.0-10.0 sec   359 MBytes   301 Mbits/sec   0.038 ms    0/256020 (0%)
[  4]  0.0-10.0 sec  1 datagrams received out-of-order

As you can see. No packet loss, low jitter. It's not my network hardware.

"ehrecv (WMC) reports an error on Tuners 1 & 4." - this happens rarely (i.e. it's not the source of my problems).

With the attached fan, temperatures stayed below 52C so I can't blame over-heating. I have a "6 dB pad", so I will try once more with that inline, in the outside chance it fixed the issue.

JohnW248 · #14

I'm not familiar with your switch, is it a managed switch? If so replace it with a dumb (i.e. cheap) 1gig switch. The less "sniffing" and "management" the better. Those things seem to always get involved along with Norton, McAfee, etc which are all bad news. If you are running any AVS software that can be an issue since they don't seem to like tv tuners streaming.

If you are running any AVS, remove it and get the makers removal tool and get it clean out. Then make sure the Windows Firewall is ON and use Windows Defender which is built in to Win 8.1. All the right ports will be open and authorized. (Personally I think everything runs better on Win7).

Let's look at the basic computer, what it is running and what protection you have on it for conflicts with TV tuners and cableCARD. I've been through a lot using this stuff since the days of OEM Vista with the ATI DCT single tuner with a max of two on a machine and only on Dell, Sony, HP, etc that were built with special Bios (That's why you have to run the Digital Cable Advisor since that's how MS opened up the requirement for cableCARD and protection. Hopefully with Win8.1 you are only running MS Defender.

There are a couple of things about MC you should be aware of: 1. Live TV has a first choice tuner which will always be called first and MC will try that and not roll to another tuner UNLESS MC itself has already used that tuner for something else. If it can't get a response (if the tuner is in use) you'll get a no video message.

2. If you are recording, however, MC will try its first choice and if no response make a send try and if no go will give a "No Video" BUT will try the next tuner and when it gets a signal will start a recording. 3. A strange behavior of MC is if it is playing live tv and loses a tuner (i.e all six tuners stop working due to power loss or the like) and MC had another tuner (like a SD Prime) it will switch to the next device and continue playing after a brief "Weak Signal" message. On the other hand if it was recording instead, the recording will be stopped and you'll find a message in the event viewer or Recorded TV history "Recording stopped, by another device" or the like. If you stop a recording, the event Viewer and Recorded TV history will show recording stopped by Jim or whoever the user is on the host machine.

So in addition to everything else you're doing you should check the messages in event viewer/windows/media center and also in Media Center Recorded TV History and look for your partial recordings. Live tv errors I don't think will show up in Media Center, but will show in Event Viewer.

Not being a Network Expert, it makes it easier for me to say it looks like this is a network issue since MC loses the signal and makes another tuner request but the tuner still tries to stream into a dead end.

There are a couple of other things you can do when this happens: 1. In the Web Gui for the Ceton Tuner, click on the LOG tab and in the command box at the lower left you can type in REBOOT and hit send which will reboot the tuner without power cycling or getting up. I always open the LOG in a new tab in IE so I can switch back and see the uptime restart and the cableCARD will be restarted as well. If only the cableCARD needs to be restarted, you can go to the Web Gui and the CableCARD tab and click "Clear Channel Map" and the cableCARD will restart and rebind and load a new channel map from the headend.

You should also be aware of the MC Services which you can stop and start (close Media Center before you do this) and that should save you having to reboot your machine.

The fact you get a "cableCARD Inserted" message is a bit troublesome but I don't have any experience with the Moto Cards. I do know that if you restart some service MC will report "cableCARD tuner found, do you want to setup Now/Later" and in the case you just click later.

You might also want to check if you're problems are happening with copy once channels (i.e. CCI 0x02) or both copy once and copy freely (CCI 0x00 or blank). If the problems are just with copy once, there might be a problem with the cableCARD pairing and authorization.

See if any of these things apply to your set up and let us know the results.

#15

JohnW248 wrote:There are a couple of other things you can do when this happens: 1. In the Web Gui for the Ceton Tuner, click on the LOG tab and in the command box at the lower left you can type in REBOOT and hit send which will reboot the tuner without power cycling or getting up. I always open the LOG in a new tab in IE so I can switch back and see the uptime restart and the cableCARD will be restarted as well. If only the cableCARD needs to be restarted, you can go to the Web Gui and the CableCARD tab and click "Clear Channel Map" and the cableCARD will restart and rebind and load a new channel map from the headend.

This was very useful info, thanks.

It is not a managed switch, it's just a good quality gigabit switch. I have a pretty vanilla setup:

Software:
Windows 8.1 64bit
Windows Firewall
Windows built in A/V
No old tuner cruft.

Hardware:
Phenom II 1045T
8GB DDR3
256 Samsung 840 SSD
GTX 460

Throughout my experiments I have been closely checking Event Viewer for insight into what's going on.

I have been pretty much only testing "Copy Free" (00) channels.

Let's forget about the CableCARD Inserted problem momentarily.

I have found a channel that seems to cause the "Viewing or Listening Conflict" error very quickly:
Channel 175, Signal Level 4.9 dBmV, SNR: 39.0 dB - everything looks great! (I added your 6db dampener).

Here is a part of a log where I restarted HTPC and Ceton and then tried to tune 175 after a couple of minutes:

Code: Select all

Jan  1 00:08:53 ocur[21]: upnp: [192.168.1.114] Action(ua[0]) GetUserActivityInterval success
Jan  1 00:08:53 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[0]) UserActivityDetected
Jan  1 00:08:53 ocur[21]: upnp: [192.168.1.114] Action(ua[0]) UserActivityDetected success
Jan  1 00:08:54 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[0]) GetCurrentConnectionInfo
Jan  1 00:08:54 ocur[21]: upnp: [192.168.1.114] Action(cm[0]) GetCurrentConnectionInfo success
Jan  1 00:08:54 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[0]) GetCurrentConnectionInfo
Jan  1 00:08:54 ocur[21]: upnp: [192.168.1.114] Action(cm[0]) GetCurrentConnectionInfo success
Jan  1 00:08:54 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[0]) GetCurrentConnectionInfo
Jan  1 00:08:54 ocur[21]: upnp: [192.168.1.114] Action(cm[0]) GetCurrentConnectionInfo success
Jan  1 00:08:54 ocur[21]: upnp: allocate[0] uuid:89333102-EBE5-11D8-AC9A-000008099EE1 c0a80172
Jan  1 00:08:54 ocur[21]: upnp: map[0]
Jan  1 00:08:54 ocur[21]: upnp: map[0] = { alloc: 1, instance: 0, udn: uuid:89333102-EBE5-11D8-AC9A-000008099EE1, client: 192.168.1.114 }
Jan  1 00:08:54 ocur[21]: upnp: map[1] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:08:54 ocur[21]: upnp: map[2] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:08:54 ocur[21]: upnp: map[3] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:08:54 ocur[21]: upnp: map[4] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:08:54 ocur[21]: upnp: map[5] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:08:54 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[0]) PrepareForConnection
Jan  1 00:08:54 ocur[21]: upnp: Event(cm[0]): CurrentConnectionIDs, "0"
Jan  1 00:08:54 ocur[21]: upnp: [192.168.1.114] Action(cm[0]) PrepareForConnection success
Jan  1 00:08:54 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 0
Jan  1 00:08:54 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:08:54 ocur[21]: ocur: [0] rtp setup for client 192.168.1.114:5001
Jan  1 00:08:55 ocur[21]: upnp: [192.168.1.114] Calling Action(av[0]) Play
Jan  1 00:08:55 ocur[21]: upnp: [192.168.1.114] Action(av[0]) Play success
Jan  1 00:08:55 ocur[21]: upnp: [192.168.1.114] Calling Action(fdc[0]) RequestTables
Jan  1 00:08:55 ocur[21]: upnp: [192.168.1.114] Action(fdc[0]) RequestTables success
Jan  1 00:08:55 ocur[21]: upnp: [192.168.1.114] Calling Action(cas[0]) SetChannel
Jan  1 00:08:55 ocur[21]: ocur: [0] Attempting to SetChannel (Channel=175  SourceId=0  Mode=0)
Jan  1 00:08:55 ocur[21]: upnp: [192.168.1.114] Action(cas[0]) SetChannel success
Jan  1 00:08:55 ocur[21]: ocur: Disabled table monitor for instance 0
Jan  1 00:08:55 ocur[21]: ocur: [0] Program number set to 0, was 1
Jan  1 00:08:55 ocur[21]: ocur: [0] Tune to 175 (mod=q256, freq=267000, program=155, std=9)
Jan  1 00:08:55 ocur[21]: ocur: [0] Program number set to 155, was 0
Jan  1 00:08:55 ocur[21]: ocur: Disabled table monitor for instance 0
Jan  1 00:08:55 ocur[21]: ocur: [0] Adding pid 0x0000
Jan  1 00:08:56 ocur[21]: ocur: [0] Locked: 0 Acc E: 0
Jan  1 00:08:56 ocur[21]: ocur: [0] Adding pid 0x1ffb
Jan  1 00:08:56 ocur[21]: upnp: [192.168.1.114] Calling Action(fdc[0]) RequestTables
Jan  1 00:08:56 ocur[21]: upnp: [192.168.1.114] Action(fdc[0]) RequestTables success
Jan  1 00:08:56 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[0]) SetCurrentTunerUseReason
Jan  1 00:08:56 ocur[21]: ocur: [0] UA: use_reason 2 TA: use_status 0
Jan  1 00:08:56 ocur[21]: upnp: [192.168.1.114] Action(ua[0]) SetCurrentTunerUseReason success
Jan  1 00:08:56 ocur[21]: ocur: [0] Tune finished to freq 267000
Jan  1 00:08:56 ocur[21]: ocur: [0] Getting pmt for program 155
Jan  1 00:08:56 ocur[21]: ocur: [0] Got pmt for program# 155
Jan  1 00:08:56 ocur[21]: ocur: [0] Adding pid 0x0030
Jan  1 00:08:56 ocur[21]: ocur: [0] Adding pid 0x0031
Jan  1 00:08:56 ocur[21]: ocur: [0] Adding pid 0x0032
Jan  1 00:08:56 ocur[21]: ocur: [0] Adding pid 0x0033
Jan  1 00:08:56 ocur[21]: ocur: [0] Adding pid 0x0034
Jan  1 00:08:56 ocur[21]: ocur: [0] Adding pid 0x0035
Jan  1 00:08:56 ocur[21]: ocur: [0] Adding pid 0x0036
Jan  1 00:08:56 ocur[21]: upnp: Event(tuner[0]): PCRLock, "1"
Jan  1 00:08:56 ocur[21]: ocur: [0] Adding pid 0x0e90
Jan  1 00:08:56 ocur[21]: ocur: [0] Adding pid 0x0105
Jan  1 00:08:56 ocur[21]: ocur: [0] Adding pid 0x0e91
Jan  1 00:08:56 ocur[21]: ocur: [0] Adding pid 0x0e92
Jan  1 00:08:56 ocur[21]: ocur: [0] Adding pid 0x0e93
Jan  1 00:08:56 ocur[21]: ocur: Disabled table monitor for instance 0
Jan  1 00:08:56 ocur[21]: ocur: Enabled table monitor for instance 0
Jan  1 00:08:56 ocur[21]: ocur: [0] Channel is scrambled, expecting CCI
Jan  1 00:08:56 ocur[21]: ocur: [0] Sending ca_pmt to CableCARD for program number 155 index 0
Jan  1 00:08:57 ocur[21]: ocur: [0] CCI 00 arrived for program# 155
Jan  1 00:08:57 ocur[21]: upnp: [192.168.1.114] Get(tuner[0]): Frequency "267000"
Jan  1 00:08:57 ocur[21]: upnp: [192.168.1.114] Get(mux[0]): ProgramNumber "155"
Jan  1 00:08:57 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[0]) UserActivityDetected
Jan  1 00:08:57 ocur[21]: upnp: [192.168.1.114] Action(ua[0]) UserActivityDetected success
Jan  1 00:08:58 ocur[21]: ocur: [0] Carrier lock is 1
Jan  1 00:09:32 ocur[21]: upnp: [192.168.1.114] Get(av[0]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg0"
Jan  1 00:09:33 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 0
Jan  1 00:09:33 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:09:33 ocur[21]: ocur: [0] rtp setup for client 192.168.1.114:5001
Jan  1 00:09:33 ocur[21]: ocur: [0] rtp teardown for client 192.168.1.114:5001
Jan  1 00:09:36 ocur[21]: upnp: [192.168.1.114] Get(av[3]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg3"
Jan  1 00:09:36 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 3
Jan  1 00:09:36 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:09:36 ocur[21]: ocur: [3] rtp setup for client 192.168.1.114:5001
Jan  1 00:09:36 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[0]) GetAuxCapabilities
Jan  1 00:09:36 ocur[21]: upnp: [192.168.1.114] Action(aux[0]) GetAuxCapabilities success
Jan  1 00:09:36 ocur[21]: ocur: [3] rtp teardown for client 192.168.1.114:5001
Jan  1 00:09:36 ocur[21]: upnp: [192.168.1.114] Get(av[1]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg1"
Jan  1 00:09:37 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 1
Jan  1 00:09:37 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012

Everything looks good until suddenly WMC reports:

Code: Select all

Jan  1 00:08:57 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[0]) UserActivityDetected
Jan  1 00:08:57 ocur[21]: upnp: [192.168.1.114] Action(ua[0]) UserActivityDetected success
[..]
Jan  1 00:09:36 ocur[21]: upnp: [192.168.1.114] Get(av[3]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg3"

I can reproduce this behaviour with a fresh system in 5 minutes. In this second case it burns through three tuners in four minutes all to watch one channel:

Code: Select all

Jan  1 00:16:48 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[3]) GetUserActivityInterval
Jan  1 00:16:48 ocur[21]: upnp: [192.168.1.114] Action(ua[3]) GetUserActivityInterval success
Jan  1 00:16:48 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[3]) UserActivityDetected
Jan  1 00:16:48 ocur[21]: upnp: [192.168.1.114] Action(ua[3]) UserActivityDetected success
Jan  1 00:16:49 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[3]) GetCurrentConnectionInfo
Jan  1 00:16:49 ocur[21]: upnp: [192.168.1.114] Action(cm[3]) GetCurrentConnectionInfo success
Jan  1 00:16:49 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[3]) GetCurrentConnectionInfo
Jan  1 00:16:49 ocur[21]: upnp: [192.168.1.114] Action(cm[3]) GetCurrentConnectionInfo success
Jan  1 00:16:49 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[3]) GetCurrentConnectionInfo
Jan  1 00:16:49 ocur[21]: upnp: [192.168.1.114] Action(cm[3]) GetCurrentConnectionInfo success
Jan  1 00:16:49 ocur[21]: upnp: allocate[3] uuid:89333102-EBE5-11D8-AC9A-000008099EE4 c0a80172
Jan  1 00:16:50 ocur[21]: upnp: map[3]
Jan  1 00:16:50 ocur[21]: upnp: map[0] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:16:50 ocur[21]: upnp: map[1] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:16:50 ocur[21]: upnp: map[2] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:16:50 ocur[21]: upnp: map[3] = { alloc: 1, instance: 3, udn: uuid:89333102-EBE5-11D8-AC9A-000008099EE4, client: 192.168.1.114 }
Jan  1 00:16:50 ocur[21]: upnp: map[4] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:16:50 ocur[21]: upnp: map[5] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:16:50 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[3]) PrepareForConnection
Jan  1 00:16:50 ocur[21]: upnp: Event(cm[3]): CurrentConnectionIDs, "0"
Jan  1 00:16:50 ocur[21]: upnp: [192.168.1.114] Action(cm[3]) PrepareForConnection success
Jan  1 00:16:50 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 3
Jan  1 00:16:50 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:16:50 ocur[21]: ocur: [3] rtp setup for client 192.168.1.114:5001
Jan  1 00:16:50 ocur[21]: upnp: [192.168.1.114] Calling Action(av[3]) Play
Jan  1 00:16:50 ocur[21]: upnp: [192.168.1.114] Action(av[3]) Play success
Jan  1 00:16:50 ocur[21]: upnp: [192.168.1.114] Calling Action(fdc[3]) RequestTables
Jan  1 00:16:50 ocur[21]: upnp: [192.168.1.114] Action(fdc[3]) RequestTables success
Jan  1 00:16:50 ocur[21]: upnp: [192.168.1.114] Calling Action(cas[3]) SetChannel
Jan  1 00:16:50 ocur[21]: ocur: [3] Attempting to SetChannel (Channel=175  SourceId=0  Mode=0)
Jan  1 00:16:50 ocur[21]: upnp: [192.168.1.114] Action(cas[3]) SetChannel success
Jan  1 00:16:50 ocur[21]: ocur: Disabled table monitor for instance 3
Jan  1 00:16:50 ocur[21]: ocur: [3] Program number set to 0, was 1
Jan  1 00:16:50 ocur[21]: ocur: [3] Tune to 175 (mod=q256, freq=267000, program=155, std=9)
Jan  1 00:16:50 ocur[21]: ocur: [3] Program number set to 155, was 0
Jan  1 00:16:50 ocur[21]: ocur: Disabled table monitor for instance 3
Jan  1 00:16:50 ocur[21]: ocur: [3] Adding pid 0x0000
Jan  1 00:16:50 ocur[21]: ocur: [3] Locked: 0 Acc E: 0
Jan  1 00:16:50 ocur[21]: ocur: [3] Adding pid 0x1ffb
Jan  1 00:16:51 ocur[21]: upnp: [192.168.1.114] Calling Action(fdc[3]) RequestTables
Jan  1 00:16:51 ocur[21]: upnp: [192.168.1.114] Action(fdc[3]) RequestTables success
Jan  1 00:16:51 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[3]) SetCurrentTunerUseReason
Jan  1 00:16:51 ocur[21]: ocur: [3] UA: use_reason 2 TA: use_status 0
Jan  1 00:16:51 ocur[21]: upnp: [192.168.1.114] Action(ua[3]) SetCurrentTunerUseReason success
Jan  1 00:16:51 ocur[21]: ocur: [3] Tune finished to freq 267000
Jan  1 00:16:51 ocur[21]: ocur: [3] Getting pmt for program 155
Jan  1 00:16:51 ocur[21]: ocur: [3] Got pmt for program# 155
Jan  1 00:16:51 ocur[21]: ocur: [3] Adding pid 0x0030
Jan  1 00:16:51 ocur[21]: ocur: [3] Adding pid 0x0031
Jan  1 00:16:51 ocur[21]: ocur: [3] Adding pid 0x0032
Jan  1 00:16:51 ocur[21]: ocur: [3] Adding pid 0x0033
Jan  1 00:16:51 ocur[21]: ocur: [3] Adding pid 0x0034
Jan  1 00:16:51 ocur[21]: ocur: [3] Adding pid 0x0035
Jan  1 00:16:51 ocur[21]: ocur: [3] Adding pid 0x0036
Jan  1 00:16:51 ocur[21]: upnp: Event(tuner[3]): PCRLock, "1"
Jan  1 00:16:51 ocur[21]: ocur: [3] Adding pid 0x0e90
Jan  1 00:16:51 ocur[21]: ocur: [3] Adding pid 0x0105
Jan  1 00:16:51 ocur[21]: ocur: [3] Adding pid 0x0e91
Jan  1 00:16:51 ocur[21]: ocur: [3] Adding pid 0x0e92
Jan  1 00:16:51 ocur[21]: ocur: [3] Adding pid 0x0e93
Jan  1 00:16:51 ocur[21]: ocur: Disabled table monitor for instance 3
Jan  1 00:16:51 ocur[21]: ocur: Enabled table monitor for instance 3
Jan  1 00:16:51 ocur[21]: ocur: [3] Channel is scrambled, expecting CCI
Jan  1 00:16:51 ocur[21]: ocur: [3] Sending ca_pmt to CableCARD for program number 155 index 0
Jan  1 00:16:52 ocur[21]: ocur: [3] CCI 00 arrived for program# 155
Jan  1 00:16:52 ocur[21]: ocur: [3] Carrier lock is 1
Jan  1 00:16:52 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[3]) UserActivityDetected
Jan  1 00:16:52 ocur[21]: upnp: [192.168.1.114] Action(ua[3]) UserActivityDetected success
Jan  1 00:16:52 ocur[21]: upnp: [192.168.1.114] Get(tuner[3]): Frequency "267000"
Jan  1 00:16:52 ocur[21]: upnp: [192.168.1.114] Get(mux[3]): ProgramNumber "155"
Jan  1 00:20:22 ocur[21]: upnp: [192.168.1.114] Get(av[4]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg4"
Jan  1 00:20:22 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 4
Jan  1 00:20:22 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:20:22 ocur[21]: ocur: [4] rtp setup for client 192.168.1.114:5001
Jan  1 00:20:22 ocur[21]: ocur: [4] rtp teardown for client 192.168.1.114:5001
Jan  1 00:20:26 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[4]) GetAuxCapabilities
Jan  1 00:20:26 ocur[21]: upnp: [192.168.1.114] Action(aux[4]) GetAuxCapabilities success
Jan  1 00:20:26 ocur[21]: upnp: [192.168.1.114] Get(av[1]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg1"
Jan  1 00:20:26 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 1
Jan  1 00:20:26 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:20:26 ocur[21]: ocur: [1] rtp setup for client 192.168.1.114:5001
Jan  1 00:20:26 ocur[21]: ocur: [1] rtp teardown for client 192.168.1.114:5001
Jan  1 00:20:26 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[4]) SetRevInfo
Jan  1 00:20:26 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[1]) GetAuxCapabilities
Jan  1 00:20:26 ocur[21]: upnp: [192.168.1.114] Action(aux[1]) GetAuxCapabilities success
Jan  1 00:20:27 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[1]) SetRevInfo
Jan  1 00:20:27 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[4]) SetRevInfo success
Jan  1 00:20:27 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[1]) SetRevInfo success
Jan  1 00:20:27 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[1]) GetAuxCapabilities
Jan  1 00:20:27 ocur[21]: upnp: [192.168.1.114] Action(aux[1]) GetAuxCapabilities success
Jan  1 00:20:27 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[4]) SetCRL
Jan  1 00:20:28 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[4]) SetCRL success
Jan  1 00:20:28 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[4]) GetAuxCapabilities
Jan  1 00:20:28 ocur[21]: upnp: [192.168.1.114] Action(aux[4]) GetAuxCapabilities success
Jan  1 00:20:28 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[1]) SetCRL
Jan  1 00:20:28 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[4]) ProcessRegistrationChallenge
Jan  1 00:20:28 ocur[21]: ocur: [4.c0a80172] Closed existing registration session
Jan  1 00:20:28 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[1]) SetCRL success
Jan  1 00:20:29 ocur[21]: ocur: [4.c0a80172] We registered
Jan  1 00:20:29 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[4]) ProcessRegistrationChallenge success
Jan  1 00:20:29 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[4]) ProcessLicenseChallenge
Jan  1 00:20:30 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[4]) ProcessLicenseChallenge success
Jan  1 00:20:31 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[1]) ProcessRegistrationChallenge
Jan  1 00:20:31 ocur[21]: ocur: [1.c0a80172] Closed existing registration session
Jan  1 00:20:31 ocur[21]: upnp: [192.168.1.114] Get(av[2]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg2"
Jan  1 00:20:31 ocur[21]: upnp: [192.168.1.114] Get(av[0]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg0"
Jan  1 00:20:31 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 2
Jan  1 00:20:31 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:20:31 ocur[21]: ocur: [2] rtp setup for client 192.168.1.114:5001
Jan  1 00:20:31 ocur[21]: ocur: [2] rtp teardown for client 192.168.1.114:5001
Jan  1 00:20:31 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 0
Jan  1 00:20:31 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:20:31 ocur[21]: ocur: [0] rtp setup for client 192.168.1.114:5001
Jan  1 00:20:31 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[2]) GetAuxCapabilities
Jan  1 00:20:31 ocur[21]: upnp: [192.168.1.114] Action(aux[2]) GetAuxCapabilities success
Jan  1 00:20:31 ocur[21]: ocur: [0] rtp teardown for client 192.168.1.114:5001
Jan  1 00:20:32 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[0]) GetAuxCapabilities
Jan  1 00:20:32 ocur[21]: upnp: [192.168.1.114] Action(aux[0]) GetAuxCapabilities success
Jan  1 00:20:32 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[2]) SetRevInfo
Jan  1 00:20:32 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[2]) SetRevInfo success
Jan  1 00:20:32 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[2]) GetAuxCapabilities
Jan  1 00:20:32 ocur[21]: upnp: [192.168.1.114] Action(aux[2]) GetAuxCapabilities success
Jan  1 00:20:32 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[2]) SetCRL
Jan  1 00:20:33 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[0]) SetRevInfo
Jan  1 00:20:33 ocur[21]: ocur: [1.c0a80172] We registered
Jan  1 00:20:33 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[1]) ProcessRegistrationChallenge success
Jan  1 00:20:33 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[2]) SetCRL success
Jan  1 00:20:33 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[0]) SetRevInfo success
Jan  1 00:20:33 ocur[21]: upnp: [192.168.1.114] Get(av[3]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg3"
Jan  1 00:20:33 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[0]) GetAuxCapabilities
Jan  1 00:20:33 ocur[21]: upnp: [192.168.1.114] Action(aux[0]) GetAuxCapabilities success
Jan  1 00:20:33 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[1]) ProcessLicenseChallenge
Jan  1 00:20:35 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[1]) ProcessLicenseChallenge success
Jan  1 00:20:35 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 3
Jan  1 00:20:35 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:20:35 ocur[21]: ocur: [3] rtp setup for client 192.168.1.114:5001
Jan  1 00:20:35 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[1]) AcknowledgeLicense
Jan  1 00:20:35 ocur[21]: ocur: [1.c0a80172] License Success Ack Received
Jan  1 00:20:35 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[1]) AcknowledgeLicense success
Jan  1 00:20:35 ocur[21]: ocur: [3] rtp teardown for client 192.168.1.114:5001
Jan  1 00:20:36 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[0]) SetCRL
Jan  1 00:20:36 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[3]) GetAuxCapabilities
Jan  1 00:20:36 ocur[21]: upnp: [192.168.1.114] Action(aux[3]) GetAuxCapabilities success
Jan  1 00:20:36 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[2]) ProcessRegistrationChallenge
Jan  1 00:20:36 ocur[21]: ocur: [2.c0a80172] Closed existing registration session
Jan  1 00:20:36 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[3]) SetRevInfo
Jan  1 00:20:36 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[0]) SetCRL success
Jan  1 00:20:36 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[3]) SetRevInfo success
Jan  1 00:20:36 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[3]) GetAuxCapabilities
Jan  1 00:20:37 ocur[21]: upnp: [192.168.1.114] Action(aux[3]) GetAuxCapabilities success
Jan  1 00:20:37 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[3]) SetCRL
Jan  1 00:20:37 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[3]) SetCRL success
Jan  1 00:20:37 ocur[21]: ocur: [2.c0a80172] We registered
Jan  1 00:20:37 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[2]) ProcessRegistrationChallenge success
Jan  1 00:20:37 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[3]) ProcessRegistrationChallenge
Jan  1 00:20:38 ocur[21]: ocur: [3.c0a80172] Closed existing registration session
Jan  1 00:20:38 ocur[21]: ocur: [3.c0a80172] We registered
Jan  1 00:20:38 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[3]) ProcessRegistrationChallenge success
Jan  1 00:20:39 ocur[21]: upnp: [192.168.1.114] Get(security[1]): HmsAssociationList "n5ByAAADTw5AAJnuAAAAAAJvgVYCELCqSWY7OUAKrDVE9BtGyWsJDd/nWutQ0z5uk9s6QfDV0QQAAAAAAABBL7mzsKpJZjs5QAqsNUT0G0bJa8FzuhftwJADcWK8KdS4wpXVBAAAAAAAAEEvubewqklmOzlACqw1RPQbR
Jan  1 00:20:39 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[2]) ProcessLicenseChallenge
Jan  1 00:20:40 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[2]) ProcessLicenseChallenge success
Jan  1 00:20:40 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[4]) AcknowledgeLicense
Jan  1 00:20:40 ocur[21]: ocur: [4.c0a80172] License Success Ack Received
Jan  1 00:20:40 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[2]) AcknowledgeLicense
Jan  1 00:20:40 ocur[21]: ocur: [2.c0a80172] License Success Ack Received
Jan  1 00:20:41 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[4]) AcknowledgeLicense success
Jan  1 00:20:41 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[2]) AcknowledgeLicense success
Jan  1 00:20:41 ocur[21]: upnp: [192.168.1.114] Get(security[2]): HmsAssociationList "n5ByAAADTw5AAJnuAAAAAAJvgVYCELCqSWY7OUAKrDVE9BtGyWsJDd/nWutQ0z5uk9s6QfDV0QQAAAAAAABBL7mzsKpJZjs5QAqsNUT0G0bJa8FzuhftwJADcWK8KdS4wpXVBAAAAAAAAEEvubewqklmOzlACqw1RPQbR
Jan  1 00:20:41 ocur[21]: upnp: [192.168.1.114] Get(security[4]): HmsAssociationList "n5ByAAADTw5AAJnuAAAAAAJvgVYCELCqSWY7OUAKrDVE9BtGyWsJDd/nWutQ0z5uk9s6QfDV0QQAAAAAAABBL7mzsKpJZjs5QAqsNUT0G0bJa8FzuhftwJADcWK8KdS4wpXVBAAAAAAAAEEvubewqklmOzlACqw1RPQbR
Jan  1 00:20:41 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[0]) ProcessRegistrationChallenge
Jan  1 00:20:41 ocur[21]: ocur: [0.c0a80172] Closed existing registration session
Jan  1 00:20:41 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[3]) GetUserActivityInterval
Jan  1 00:20:41 ocur[21]: upnp: [192.168.1.114] Action(ua[3]) GetUserActivityInterval success
Jan  1 00:20:41 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[3]) UserActivityDetected
Jan  1 00:20:41 ocur[21]: upnp: [192.168.1.114] Action(ua[3]) UserActivityDetected success
Jan  1 00:20:42 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[3]) GetCurrentConnectionInfo
Jan  1 00:20:42 ocur[21]: upnp: [192.168.1.114] Action(cm[3]) GetCurrentConnectionInfo success
Jan  1 00:20:42 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[3]) GetCurrentConnectionInfo
Jan  1 00:20:42 ocur[21]: upnp: [192.168.1.114] Action(cm[3]) GetCurrentConnectionInfo success
Jan  1 00:20:42 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[3]) GetCurrentConnectionInfo
Jan  1 00:20:42 ocur[21]: upnp: [192.168.1.114] Action(cm[3]) GetCurrentConnectionInfo success
Jan  1 00:20:43 ocur[21]: upnp: allocate[3] uuid:89333102-EBE5-11D8-AC9A-000008099EE4 c0a80172
Jan  1 00:20:43 ocur[21]: upnp: remap[3->0] uuid:89333102-EBE5-11D8-AC9A-000008099EE4
Jan  1 00:20:43 ocur[21]: upnp: map[0] = { alloc: 1, instance: 3, udn: uuid:89333102-EBE5-11D8-AC9A-000008099EE4, client: 192.168.1.114 }
Jan  1 00:20:43 ocur[21]: upnp: map[1] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:20:43 ocur[21]: upnp: map[2] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:20:43 ocur[21]: upnp: map[3] = { alloc: 1, instance: 3, udn: uuid:89333102-EBE5-11D8-AC9A-000008099EE4, client: 192.168.1.114 }
Jan  1 00:20:43 ocur[21]: upnp: map[4] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:20:43 ocur[21]: upnp: map[5] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:20:43 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[0]) PrepareForConnection
Jan  1 00:20:43 ocur[21]: ocur: [0.c0a80172] We registered
Jan  1 00:20:43 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[0]) ProcessRegistrationChallenge success
Jan  1 00:20:43 ocur[21]: upnp: Event(cm[0]): CurrentConnectionIDs, "0"
Jan  1 00:20:43 ocur[21]: upnp: [192.168.1.114] Action(cm[0]) PrepareForConnection success
Jan  1 00:20:43 ocur[21]: upnp: lookup mapped 3->0
Jan  1 00:20:43 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 0
Jan  1 00:20:43 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:20:43 ocur[21]: ocur: [0] rtp setup for client 192.168.1.114:5001
Jan  1 00:20:43 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[3]) ProcessLicenseChallenge
Jan  1 00:20:43 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[0]) ProcessLicenseChallenge
Jan  1 00:20:45 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[3]) ProcessLicenseChallenge success
Jan  1 00:20:45 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[0]) ProcessLicenseChallenge success
Jan  1 00:20:46 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[0]) AcknowledgeLicense
Jan  1 00:20:46 ocur[21]: upnp: [192.168.1.114] Calling Action(av[0]) Play
Jan  1 00:20:46 ocur[21]: ocur: [0.c0a80172] License Success Ack Received
Jan  1 00:20:46 ocur[21]: upnp: [192.168.1.114] Action(av[0]) Play success
Jan  1 00:20:46 ocur[21]: upnp: reverse lookup 3->0
Jan  1 00:20:46 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[0]) AcknowledgeLicense success
Jan  1 00:20:46 ocur[21]: upnp: [192.168.1.114] Get(security[0]): HmsAssociationList "n5ByAAADTw5AAJnuAAAAAAJvgVYDELCqSWY7OUAKrDVE9BtGyWsJDd/nWutQ0z5uk9s6QfDV0QQAAAAAAABBL7mzsKpJZjs5QAqsNUT0G0bJa8FzuhftwJADcWK8KdS4wpXVBAAAAAAAAEEvubewqklmOzlACqw1RPQbR
Jan  1 00:20:46 ocur[21]: upnp: [192.168.1.114] Get(av[5]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg5"
Jan  1 00:20:46 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[3]) AcknowledgeLicense
Jan  1 00:20:46 ocur[21]: ocur: [3.c0a80172] License Success Ack Received
Jan  1 00:20:46 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[3]) AcknowledgeLicense success
Jan  1 00:20:46 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 5
Jan  1 00:20:46 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:20:46 ocur[21]: ocur: [5] rtp setup for client 192.168.1.114:5001
Jan  1 00:20:46 ocur[21]: ocur: [5] rtp teardown for client 192.168.1.114:5001
Jan  1 00:20:46 ocur[21]: upnp: [192.168.1.114] Calling Action(fdc[0]) RequestTables
Jan  1 00:20:46 ocur[21]: upnp: [192.168.1.114] Action(fdc[0]) RequestTables success
Jan  1 00:20:46 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[5]) GetAuxCapabilities
Jan  1 00:20:46 ocur[21]: upnp: [192.168.1.114] Action(aux[5]) GetAuxCapabilities success
Jan  1 00:20:46 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[5]) SetRevInfo
Jan  1 00:20:47 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[5]) SetRevInfo success
Jan  1 00:20:47 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[5]) GetAuxCapabilities
Jan  1 00:20:47 ocur[21]: upnp: [192.168.1.114] Action(aux[5]) GetAuxCapabilities success
Jan  1 00:20:47 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[5]) SetCRL
Jan  1 00:20:47 ocur[21]: upnp: [192.168.1.114] Get(security[0]): HmsAssociationList "n5ByAAADTw5AAJnuAAAAAAJvgVYDELCqSWY7OUAKrDVE9BtGyWsJDd/nWutQ0z5uk9s6QfDV0QQAAAAAAABBL7mzsKpJZjs5QAqsNUT0G0bJa8FzuhftwJADcWK8KdS4wpXVBAAAAAAAAEEvubewqklmOzlACqw1RPQbR
Jan  1 00:20:47 ocur[21]: upnp: [192.168.1.114] Calling Action(cas[0]) SetChannel
Jan  1 00:20:47 ocur[21]: ocur: [0] Attempting to SetChannel (Channel=175  SourceId=0  Mode=0)
Jan  1 00:20:47 ocur[21]: ocur: Disabled table monitor for instance 0
Jan  1 00:20:47 ocur[21]: upnp: [192.168.1.114] Action(cas[0]) SetChannel success
Jan  1 00:20:47 ocur[21]: ocur: [0] Program number set to 0, was 1
Jan  1 00:20:47 ocur[21]: ocur: [0] Tune to 175 (mod=q256, freq=267000, program=155, std=9)
Jan  1 00:20:47 ocur[21]: ocur: [0] Program number set to 155, was 0
Jan  1 00:20:47 ocur[21]: ocur: Disabled table monitor for instance 0
Jan  1 00:20:47 ocur[21]: ocur: [0] Adding pid 0x0000
Jan  1 00:20:47 ocur[21]: ocur: [0] Locked: 0 Acc E: 0
Jan  1 00:20:47 ocur[21]: ocur: [0] Adding pid 0x1ffb
Jan  1 00:20:47 ocur[21]: upnp: [192.168.1.114] Calling Action(fdc[0]) RequestTables
Jan  1 00:20:47 ocur[21]: upnp: [192.168.1.114] Action(fdc[0]) RequestTables success
Jan  1 00:20:47 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[0]) SetCurrentTunerUseReason
Jan  1 00:20:47 ocur[21]: ocur: [0] UA: use_reason 2 TA: use_status 0
Jan  1 00:20:48 ocur[21]: upnp: [192.168.1.114] Action(ua[0]) SetCurrentTunerUseReason success
Jan  1 00:20:48 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[5]) SetCRL success
Jan  1 00:20:48 ocur[21]: ocur: [0] Tune finished to freq 267000
Jan  1 00:20:48 ocur[21]: ocur: [0] Getting pmt for program 155
Jan  1 00:20:48 ocur[21]: ocur: [0] Got pmt for program# 155
Jan  1 00:20:48 ocur[21]: ocur: [0] Adding pid 0x0030
Jan  1 00:20:48 ocur[21]: ocur: [0] Adding pid 0x0031
Jan  1 00:20:48 ocur[21]: ocur: [0] Adding pid 0x0032
Jan  1 00:20:48 ocur[21]: ocur: [0] Adding pid 0x0033
Jan  1 00:20:48 ocur[21]: ocur: [0] Adding pid 0x0034
Jan  1 00:20:48 ocur[21]: ocur: [0] Adding pid 0x0035
Jan  1 00:20:48 ocur[21]: ocur: [0] Adding pid 0x0036
Jan  1 00:20:49 ocur[21]: upnp: Event(tuner[0]): PCRLock, "1"
Jan  1 00:20:49 ocur[21]: ocur: [0] Adding pid 0x0e90
Jan  1 00:20:49 ocur[21]: ocur: [0] Adding pid 0x0105
Jan  1 00:20:49 ocur[21]: ocur: [0] Adding pid 0x0e91
Jan  1 00:20:49 ocur[21]: ocur: [0] Adding pid 0x0e92
Jan  1 00:20:49 ocur[21]: ocur: [0] Adding pid 0x0e93
Jan  1 00:20:49 ocur[21]: ocur: Disabled table monitor for instance 0
Jan  1 00:20:49 ocur[21]: ocur: Enabled table monitor for instance 0
Jan  1 00:20:49 ocur[21]: ocur: [0] Channel is scrambled, expecting CCI
Jan  1 00:20:49 ocur[21]: ocur: [0] Sending ca_pmt to CableCARD for program number 155 index 1
Jan  1 00:20:49 ocur[21]: ocur: [0] Carrier lock is 1
Jan  1 00:20:50 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[5]) ProcessRegistrationChallenge
Jan  1 00:20:50 ocur[21]: ocur: [5.c0a80172] Closed existing registration session
Jan  1 00:20:51 ocur[21]: ocur: [0] CCI 00 arrived for program# 155
Jan  1 00:20:51 ocur[21]: ocur: [5.c0a80172] We registered
Jan  1 00:20:51 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[5]) ProcessRegistrationChallenge success
Jan  1 00:20:51 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[5]) ProcessLicenseChallenge
Jan  1 00:20:53 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[5]) ProcessLicenseChallenge success
Jan  1 00:20:55 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[5]) AcknowledgeLicense
Jan  1 00:20:55 ocur[21]: ocur: [5.c0a80172] License Success Ack Received
Jan  1 00:20:55 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[5]) AcknowledgeLicense success
Jan  1 00:20:56 ocur[21]: upnp: [192.168.1.114] Get(security[5]): HmsAssociationList "n5ByAAADTw5AAJnuAAAAAAJvgVYEELCqSWY7OUAKrDVE9BtGyWsJDd/nWutQ0z5uk9s6QfDV0QQAAAAAAABBL7mzsKpJZjs5QAqsNUT0G0bJa8FzuhftwJADcWK8KdS4wpXVBAAAAAAAAEEvubewqklmOzlACqw1RPQbR
Jan  1 00:20:56 ocur[21]: upnp: [192.168.1.114] Get(tuner[0]): Frequency "267000"
Jan  1 00:20:56 ocur[21]: upnp: [192.168.1.114] Get(mux[0]): ProgramNumber "155"
Jan  1 00:20:56 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[0]) UserActivityDetected
Jan  1 00:20:56 ocur[21]: upnp: [192.168.1.114] Action(ua[0]) UserActivityDetected success
Jan  1 00:21:46 ocur[21]: upnp: [192.168.1.114] Get(av[4]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg4"
Jan  1 00:21:46 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 4
Jan  1 00:21:46 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:21:46 ocur[21]: ocur: [4] rtp setup for client 192.168.1.114:5001
Jan  1 00:21:46 ocur[21]: ocur: [4] rtp teardown for client 192.168.1.114:5001
Jan  1 00:21:47 ocur[21]: upnp: [192.168.1.114] Get(av[1]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg1"
Jan  1 00:21:47 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 1
Jan  1 00:21:47 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:21:47 ocur[21]: ocur: [1] rtp setup for client 192.168.1.114:5001
Jan  1 00:21:47 ocur[21]: ocur: [1] rtp teardown for client 192.168.1.114:5001
Jan  1 00:21:48 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[1]) GetAuxCapabilities
Jan  1 00:21:48 ocur[21]: upnp: [192.168.1.114] Action(aux[1]) GetAuxCapabilities success
Jan  1 00:21:48 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[1]) GetAuxCapabilities
Jan  1 00:21:48 ocur[21]: upnp: [192.168.1.114] Action(aux[1]) GetAuxCapabilities success
Jan  1 00:21:48 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[1]) SetRevInfo
Jan  1 00:21:49 ocur[21]: upnp: [192.168.1.114] Get(av[2]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg2"
Jan  1 00:21:49 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 2
Jan  1 00:21:49 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:21:49 ocur[21]: ocur: [2] rtp setup for client 192.168.1.114:5001
Jan  1 00:21:49 ocur[21]: ocur: [2] rtp teardown for client 192.168.1.114:5001
Jan  1 00:21:49 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[2]) GetAuxCapabilities
Jan  1 00:21:49 ocur[21]: upnp: [192.168.1.114] Action(aux[2]) GetAuxCapabilities success
Jan  1 00:21:49 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[1]) SetRevInfo success
Jan  1 00:21:49 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[2]) SetRevInfo
Jan  1 00:21:49 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[4]) GetAuxCapabilities
Jan  1 00:21:49 ocur[21]: upnp: [192.168.1.114] Action(aux[4]) GetAuxCapabilities success
Jan  1 00:21:49 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[4]) SetRevInfo
Jan  1 00:21:50 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[2]) SetRevInfo success
Jan  1 00:21:50 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[4]) SetRevInfo success
Jan  1 00:21:50 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[2]) GetAuxCapabilities
Jan  1 00:21:50 ocur[21]: upnp: [192.168.1.114] Action(aux[2]) GetAuxCapabilities success
Jan  1 00:21:50 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[4]) GetAuxCapabilities
Jan  1 00:21:50 ocur[21]: upnp: [192.168.1.114] Action(aux[4]) GetAuxCapabilities success
Jan  1 00:21:50 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[1]) SetCRL
Jan  1 00:21:50 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[1]) SetCRL success
Jan  1 00:21:51 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[4]) SetCRL
Jan  1 00:21:51 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[2]) SetCRL
Jan  1 00:21:51 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[2]) SetCRL success
Jan  1 00:21:51 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[4]) SetCRL success
Jan  1 00:21:51 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[4]) ProcessRegistrationChallenge
Jan  1 00:21:51 ocur[21]: ocur: [4.c0a80172] Closed existing registration session
Jan  1 00:21:52 ocur[21]: ocur: [4.c0a80172] We registered
Jan  1 00:21:52 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[4]) ProcessRegistrationChallenge success
Jan  1 00:21:52 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[1]) ProcessRegistrationChallenge
Jan  1 00:21:52 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[2]) ProcessRegistrationChallenge
Jan  1 00:21:53 ocur[21]: ocur: [1.c0a80172] Closed existing registration session
Jan  1 00:21:53 ocur[21]: ocur: [2.c0a80172] Closed existing registration session
Jan  1 00:21:53 ocur[21]: ocur: [1.c0a80172] We registered
Jan  1 00:21:53 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[1]) ProcessRegistrationChallenge success
Jan  1 00:21:54 ocur[21]: ocur: [2.c0a80172] We registered
Jan  1 00:21:54 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[2]) ProcessRegistrationChallenge success
Jan  1 00:21:55 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[2]) ProcessLicenseChallenge
Jan  1 00:21:56 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[2]) ProcessLicenseChallenge success
Jan  1 00:21:57 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[2]) AcknowledgeLicense
Jan  1 00:21:57 ocur[21]: ocur: [2.c0a80172] License Success Ack Received
Jan  1 00:21:57 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[2]) AcknowledgeLicense success
Jan  1 00:21:57 ocur[21]: upnp: [192.168.1.114] Get(security[2]): HmsAssociationList "n5ByAAADTw5AAJnuAAAAAAJvgVYHELCqSWY7OUAKrDVE9BtGyWsJDd/nWutQ0z5uk9s6QfDV0QQAAAAAAABBL7mzsKpJZjs5QAqsNUT0G0bJa8FzuhftwJADcWK8KdS4wpXVBAAAAAAAAEEvubewqklmOzlACqw1RPQbR
Jan  1 00:21:57 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[4]) ProcessLicenseChallenge
Jan  1 00:21:58 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[4]) ProcessLicenseChallenge success
Jan  1 00:21:58 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[4]) AcknowledgeLicense
Jan  1 00:21:58 ocur[21]: ocur: [4.c0a80172] License Success Ack Received
Jan  1 00:21:58 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[4]) AcknowledgeLicense success
Jan  1 00:21:58 ocur[21]: upnp: [192.168.1.114] Get(security[4]): HmsAssociationList "n5ByAAADTw5AAJnuAAAAAAJvgVYHELCqSWY7OUAKrDVE9BtGyWsJDd/nWutQ0z5uk9s6QfDV0QQAAAAAAABBL7mzsKpJZjs5QAqsNUT0G0bJa8FzuhftwJADcWK8KdS4wpXVBAAAAAAAAEEvubewqklmOzlACqw1RPQbR
Jan  1 00:21:58 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[1]) ProcessLicenseChallenge
Jan  1 00:21:59 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[1]) ProcessLicenseChallenge success
Jan  1 00:22:00 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[1]) AcknowledgeLicense
Jan  1 00:22:00 ocur[21]: ocur: [1.c0a80172] License Success Ack Received
Jan  1 00:22:00 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[1]) AcknowledgeLicense success
Jan  1 00:22:00 ocur[21]: upnp: [192.168.1.114] Get(security[1]): HmsAssociationList "n5ByAAADTw5AAJnuAAAAAAJvgVYHELCqSWY7OUAKrDVE9BtGyWsJDd/nWutQ0z5uk9s6QfDV0QQAAAAAAABBL7mzsKpJZjs5QAqsNUT0G0bJa8FzuhftwJADcWK8KdS4wpXVBAAAAAAAAEEvubewqklmOzlACqw1RPQbR
Jan  1 00:22:00 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[4]) GetUserActivityInterval
Jan  1 00:22:00 ocur[21]: upnp: [192.168.1.114] Action(ua[4]) GetUserActivityInterval success
Jan  1 00:22:01 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[4]) UserActivityDetected
Jan  1 00:22:01 ocur[21]: upnp: [192.168.1.114] Action(ua[4]) UserActivityDetected success
Jan  1 00:22:01 ocur[21]: upnp: [192.168.1.114] Get(av[3]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg3"
Jan  1 00:22:01 ocur[21]: upnp: lookup mapped 3->0
Jan  1 00:22:01 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 0
Jan  1 00:22:01 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:22:01 ocur[21]: ocur: [0] rtp setup for client 192.168.1.114:5001
Jan  1 00:22:01 ocur[21]: upnp: lookup mapped 3->0
Jan  1 00:22:01 ocur[21]: ocur: [0] rtp teardown for client 192.168.1.114:5001
Jan  1 00:22:02 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[0]) GetAuxCapabilities
Jan  1 00:22:02 ocur[21]: upnp: [192.168.1.114] Action(aux[0]) GetAuxCapabilities success
Jan  1 00:22:02 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[3]) SetRevInfo
Jan  1 00:22:02 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[3]) SetRevInfo success
Jan  1 00:22:02 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[0]) GetAuxCapabilities
Jan  1 00:22:02 ocur[21]: upnp: [192.168.1.114] Action(aux[0]) GetAuxCapabilities success
Jan  1 00:22:02 ocur[21]: upnp: [192.168.1.114] Get(av[0]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg0"
Jan  1 00:22:03 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[3]) SetCRL
Jan  1 00:22:03 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 0
Jan  1 00:22:03 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:22:03 ocur[21]: ocur: [0] rtp setup for client 192.168.1.114:5001
Jan  1 00:22:03 ocur[21]: ocur: [0] rtp teardown for client 192.168.1.114:5001
Jan  1 00:22:03 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[0]) GetAuxCapabilities
Jan  1 00:22:03 ocur[21]: upnp: [192.168.1.114] Action(aux[0]) GetAuxCapabilities success
Jan  1 00:22:03 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[0]) SetRevInfo
Jan  1 00:22:03 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[3]) SetCRL success
Jan  1 00:22:03 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[0]) SetRevInfo success
Jan  1 00:22:03 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[0]) GetAuxCapabilities
Jan  1 00:22:03 ocur[21]: upnp: [192.168.1.114] Action(aux[0]) GetAuxCapabilities success
Jan  1 00:22:03 ocur[21]: upnp: [192.168.1.114] Get(av[5]): AVTransportURI "rtsp://192.168.1.122:8554/cetonmpeg5"
Jan  1 00:22:03 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 5
Jan  1 00:22:03 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:22:03 ocur[21]: ocur: [5] rtp setup for client 192.168.1.114:5001
Jan  1 00:22:04 ocur[21]: ocur: [5] rtp teardown for client 192.168.1.114:5001
Jan  1 00:22:04 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[0]) SetCRL
Jan  1 00:22:04 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[5]) GetAuxCapabilities
Jan  1 00:22:04 ocur[21]: upnp: [192.168.1.114] Action(aux[5]) GetAuxCapabilities success
Jan  1 00:22:04 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[3]) ProcessRegistrationChallenge
Jan  1 00:22:04 ocur[21]: ocur: [3.c0a80172] Closed existing registration session
Jan  1 00:22:04 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[5]) SetRevInfo
Jan  1 00:22:04 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[0]) SetCRL success
Jan  1 00:22:05 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[5]) SetRevInfo success
Jan  1 00:22:05 ocur[21]: upnp: [192.168.1.114] Calling Action(aux[5]) GetAuxCapabilities
Jan  1 00:22:05 ocur[21]: upnp: [192.168.1.114] Action(aux[5]) GetAuxCapabilities success
Jan  1 00:22:05 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[5]) SetCRL
Jan  1 00:22:05 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[5]) SetCRL success
Jan  1 00:22:05 ocur[21]: ocur: [3.c0a80172] We registered
Jan  1 00:22:05 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[3]) ProcessRegistrationChallenge success
Jan  1 00:22:06 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[5]) ProcessRegistrationChallenge
Jan  1 00:22:06 ocur[21]: ocur: [5.c0a80172] Closed existing registration session
Jan  1 00:22:06 ocur[21]: ocur: [5.c0a80172] We registered
Jan  1 00:22:06 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[5]) ProcessRegistrationChallenge success
Jan  1 00:22:07 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[5]) ProcessLicenseChallenge
Jan  1 00:22:07 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[3]) ProcessLicenseChallenge
Jan  1 00:22:09 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[3]) ProcessLicenseChallenge success
Jan  1 00:22:09 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[5]) ProcessLicenseChallenge success
Jan  1 00:22:09 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[3]) AcknowledgeLicense
Jan  1 00:22:09 ocur[21]: ocur: [3.c0a80172] License Success Ack Received
Jan  1 00:22:09 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[3]) AcknowledgeLicense success
Jan  1 00:22:09 ocur[21]: upnp: [192.168.1.114] Get(security[0]): HmsAssociationList "n5ByAAADTw5AAJnuAAAAAAJvgVYJELCqSWY7OUAKrDVE9BtGyWsJDd/nWutQ0z5uk9s6QfDV0QQAAAAAAABBL7mzsKpJZjs5QAqsNUT0G0bJa8FzuhftwJADcWK8KdS4wpXVBAAAAAAAAEEvubewqklmOzlACqw1RPQbR
Jan  1 00:22:10 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[5]) AcknowledgeLicense
Jan  1 00:22:10 ocur[21]: ocur: [5.c0a80172] License Success Ack Received
Jan  1 00:22:10 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[5]) AcknowledgeLicense success
Jan  1 00:22:10 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[0]) ProcessRegistrationChallenge
Jan  1 00:22:10 ocur[21]: ocur: [0.c0a80172] Closed existing registration session
Jan  1 00:22:11 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[4]) UserActivityDetected
Jan  1 00:22:11 ocur[21]: upnp: [192.168.1.114] Action(ua[4]) UserActivityDetected success
Jan  1 00:22:12 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[4]) GetCurrentConnectionInfo
Jan  1 00:22:12 ocur[21]: upnp: [192.168.1.114] Action(cm[4]) GetCurrentConnectionInfo success
Jan  1 00:22:12 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[4]) GetCurrentConnectionInfo
Jan  1 00:22:12 ocur[21]: upnp: [192.168.1.114] Action(cm[4]) GetCurrentConnectionInfo success
Jan  1 00:22:13 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[4]) GetCurrentConnectionInfo
Jan  1 00:22:13 ocur[21]: upnp: [192.168.1.114] Action(cm[4]) GetCurrentConnectionInfo success
Jan  1 00:22:13 ocur[21]: upnp: allocate[4] uuid:89333102-EBE5-11D8-AC9A-000008099EE5 c0a80172
Jan  1 00:22:13 ocur[21]: upnp: map[4]
Jan  1 00:22:13 ocur[21]: upnp: map[0] = { alloc: 1, instance: 3, udn: uuid:89333102-EBE5-11D8-AC9A-000008099EE4, client: 192.168.1.114 }
Jan  1 00:22:13 ocur[21]: upnp: map[1] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:22:13 ocur[21]: upnp: map[2] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:22:13 ocur[21]: upnp: map[3] = { alloc: 1, instance: 3, udn: uuid:89333102-EBE5-11D8-AC9A-000008099EE4, client: 192.168.1.114 }
Jan  1 00:22:13 ocur[21]: upnp: map[4] = { alloc: 1, instance: 4, udn: uuid:89333102-EBE5-11D8-AC9A-000008099EE5, client: 192.168.1.114 }
Jan  1 00:22:13 ocur[21]: upnp: map[5] = { alloc: 0, instance: -1, udn: (null), client: 0.0.0.0 }
Jan  1 00:22:13 ocur[21]: upnp: [192.168.1.114] Calling Action(cm[4]) PrepareForConnection
Jan  1 00:22:13 ocur[21]: upnp: Event(cm[4]): CurrentConnectionIDs, "0"
Jan  1 00:22:13 ocur[21]: upnp: [192.168.1.114] Action(cm[4]) PrepareForConnection success
Jan  1 00:22:13 ocur[21]: libctn91xx: Setting mpeg_eth headers for instance 4
Jan  1 00:22:13 ocur[21]: libctn91xx: rip C0A80172 lip C0A8017A rp 5001 lp 43012
Jan  1 00:22:13 ocur[21]: ocur: [4] rtp setup for client 192.168.1.114:5001
Jan  1 00:22:13 ocur[21]: upnp: [192.168.1.114] Calling Action(av[4]) Play
Jan  1 00:22:13 ocur[21]: upnp: [192.168.1.114] Action(av[4]) Play success
Jan  1 00:22:13 ocur[21]: upnp: [192.168.1.114] Calling Action(fdc[4]) RequestTables
Jan  1 00:22:13 ocur[21]: upnp: [192.168.1.114] Action(fdc[4]) RequestTables success
Jan  1 00:22:13 ocur[21]: ocur: [0.c0a80172] We registered
Jan  1 00:22:13 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[0]) ProcessRegistrationChallenge success
Jan  1 00:22:14 ocur[21]: upnp: [192.168.1.114] Get(security[5]): HmsAssociationList "n5ByAAADTw5AAJnuAAAAAAJvgVYKELCqSWY7OUAKrDVE9BtGyWsJDd/nWutQ0z5uk9s6QfDV0QQAAAAAAABBL7mzsKpJZjs5QAqsNUT0G0bJa8FzuhftwJADcWK8KdS4wpXVBAAAAAAAAEEvubewqklmOzlACqw1RPQbR
Jan  1 00:22:14 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[0]) ProcessLicenseChallenge
Jan  1 00:22:20 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[0]) ProcessLicenseChallenge success
Jan  1 00:22:20 ocur[21]: upnp: [192.168.1.114] Calling Action(wmdrm[0]) AcknowledgeLicense
Jan  1 00:22:21 ocur[21]: ocur: [0.c0a80172] License Success Ack Received
Jan  1 00:22:21 ocur[21]: upnp: [192.168.1.114] Action(wmdrm[0]) AcknowledgeLicense success
Jan  1 00:22:21 ocur[21]: upnp: reverse lookup 3->0
Jan  1 00:22:21 ocur[21]: upnp: [192.168.1.114] Get(security[0]): HmsAssociationList "n5ByAAADTw5AAJnuAAAAAAJvgVYKELCqSWY7OUAKrDVE9BtGyWsJDd/nWutQ0z5uk9s6QfDV0QQAAAAAAABBL7mzsKpJZjs5QAqsNUT0G0bJa8FzuhftwJADcWK8KdS4wpXVBAAAAAAAAEEvubewqklmOzlACqw1RPQbR
Jan  1 00:22:21 ocur[21]: upnp: [192.168.1.114] Calling Action(cas[4]) SetChannel
Jan  1 00:22:21 ocur[21]: ocur: [4] Attempting to SetChannel (Channel=175  SourceId=0  Mode=0)
Jan  1 00:22:21 ocur[21]: upnp: [192.168.1.114] Action(cas[4]) SetChannel success
Jan  1 00:22:21 ocur[21]: ocur: Disabled table monitor for instance 4
Jan  1 00:22:21 ocur[21]: ocur: [4] Program number set to 0, was 1
Jan  1 00:22:21 ocur[21]: ocur: [4] Tune to 175 (mod=q256, freq=267000, program=155, std=9)
Jan  1 00:22:21 ocur[21]: ocur: [4] Program number set to 155, was 0
Jan  1 00:22:21 ocur[21]: ocur: Disabled table monitor for instance 4
Jan  1 00:22:22 ocur[21]: ocur: [4] Adding pid 0x0000
Jan  1 00:22:22 ocur[21]: ocur: [4] Locked: 0 Acc E: 0
Jan  1 00:22:22 ocur[21]: ocur: [4] Adding pid 0x1ffb
Jan  1 00:22:22 ocur[21]: upnp: [192.168.1.114] Calling Action(fdc[4]) RequestTables
Jan  1 00:22:22 ocur[21]: upnp: [192.168.1.114] Action(fdc[4]) RequestTables success
Jan  1 00:22:23 ocur[21]: upnp: [192.168.1.114] Calling Action(ua[4]) SetCurrentTunerUseReason
Jan  1 00:22:23 ocur[21]: ocur: [4] UA: use_reason 2 TA: use_status 0
Jan  1 00:22:23 ocur[21]: upnp: [192.168.1.114] Action(ua[4]) SetCurrentTunerUseReason success
Jan  1 00:22:23 ocur[21]: ocur: [4] Tune finished to freq 267000
Jan  1 00:22:23 ocur[21]: ocur: [4] Getting pmt for program 155
Jan  1 00:22:23 ocur[21]: ocur: [4] Got pmt for program# 155
Jan  1 00:22:23 ocur[21]: ocur: [4] Adding pid 0x0030
Jan  1 00:22:23 ocur[21]: ocur: [4] Adding pid 0x0031
Jan  1 00:22:23 ocur[21]: ocur: [4] Adding pid 0x0032
Jan  1 00:22:23 ocur[21]: ocur: [4] Adding pid 0x0033
Jan  1 00:22:23 ocur[21]: ocur: [4] Adding pid 0x0034
Jan  1 00:22:23 ocur[21]: ocur: [4] Adding pid 0x0035
Jan  1 00:22:23 ocur[21]: ocur: [4] Adding pid 0x0036
Jan  1 00:22:24 ocur[21]: upnp: Event(tuner[4]): PCRLock, "1"
Jan  1 00:22:24 ocur[21]: ocur: [4] Adding pid 0x0e90
Jan  1 00:22:24 ocur[21]: ocur: [4] Adding pid 0x0105
Jan  1 00:22:24 ocur[21]: ocur: [4] Adding pid 0x0e91
Jan  1 00:22:24 ocur[21]: ocur: [4] Adding pid 0x0e92
Jan  1 00:22:24 ocur[21]: ocur: [4] Adding pid 0x0e93
Jan  1 00:22:24 ocur[21]: ocur: Disabled table monitor for instance 4
Jan  1 00:22:24 ocur[21]: ocur: Enabled table monitor for instance 4
Jan  1 00:22:24 ocur[21]: ocur: [4] Channel is scrambled, expecting CCI
Jan  1 00:22:24 ocur[21]: ocur: [4] Sending ca_pmt to CableCARD for program number 155 index 2
Jan  1 00:22:25 ocur[21]: ocur: [4] CCI 00 arrived for program# 155
Jan  1 00:22:25 ocur[21]: upnp: [192.168.1.114] Get(tuner[4]): Frequency "267000"
Jan  1 00:22:26 ocur[21]: upnp: [192.168.1.114] Get(mux[4]): ProgramNumber "155"
Jan  1 00:22:26 ocur[21]: ocur: [4] Carrier lock is 1

JohnW248 · #16

Have you opened a ticket with Ceton and taken a diagnostic as soon as you get the no tuners/conflict message? Are the tuners showing WMDRM as Green on all tuners?

I just didn't notice a challenge and pairing in your first example which looked like it was from a boot of the tuner.

Ceton can tell for sure, but it looks like there is a connection issue between the tuner and the computer---why I don't know. Network drivers, settings? Some 3rd party program? But if you give them a good set of diagnostics they can ferret this out. Why one channel would hit this sooner is a bit of a mystery unless you're in a Comcast MPEG4 test area.

Since you're in a large copy freely area, have you looked at the recording in Nero or VideoReDo and checked modulation and sound encoding for anything "strange"?

Has Comcast checked your drop for any signal "intrusion" or some type of interference that could be coming intermittently and "killing the tune"? Since you found a channel where it happens often and fast, that might be a clue to some coax problem incoming to you. I don't know how your system is constructed, if its fiber from the headend to a node and then offloads to coax or if its a coax build. If the latter there are lots more places where intrusion can hit or a bad amp might have a PS that is spiking, etc. All these are guesses, but the Comcast Techs should have tools to check out the cable and the channel you just discovered might be a second or third harmonic to the trouble source. (A fiber node build is more likely if you have video on demand which can be ordered from a STB remote.)

#17

JohnW248 - You're a patient guy!

I started a ticket with Ceton when I still had the external filter on my line, so it was a large list of issues. I'll start a new one, but I'll be honest I wasn't too impressed with how the first one went, hence me pursuing the issue here.

WMDRM always shows Green for all tuners.

"challenge and pairing" - what does this look like?

I agree that one channel being more prone to the problem is very odd and in my mind suggests it's not my hardware.

Above I show that with the same configuration of switch and CAT5e cables, I can stream 300mbit via UDP with zero packet loss and no jitter. Doesn't this essentially prove that my networking hardware configuration can't be at fault?

If there were signal drop-outs or intermittent signal issues wouldn't I see it in my logs of the signal level and SNR? They always remain consistent (rock solid actually) throughout my tests. You can imagine I don't want to go near Comcast with this issue unless I have to! I have VOD available at my location.

Tonight I will test behaviour using my other HTPC on its own and I'll also try with iperf or similar running in the background to see if there is any variation when the tuner drops out.

JohnW248 · #18

There could be a few other things to check, but they are Comcast related. If you are experiencing any problem with the OOB signal or the CA Stream, that might explain the problem as well. I don't know how the encryption scheme works on Moto systems, but on Cisco the CA stream after authorization gets updated every 10 minuets, if the OOB signal drops for a moment or there are DAVIC errors, that could cause a channel to drop.

Here are examples of the Cisco CableCARD tabs.
Cisco CableCARD(tm)
Conditional Access Details

System Id: 0x0E00
Status: Ready
Internal Secure Micro Serial No:
02:08:00:52:39:B3
Secure Micro Software Ver:
3.14
CA Time:
Tue Sep 2 2014, 4:13:00 AM GMT
Time GBAM: 16403
App GBAM: 0
Purchase GBAM: 0
EMMs Processed: 0 >>>this number increments as entitlement message are received from the headend. It resets to zero when you reboot the tuner or the cableCARD.

Cisco CableCARD(tm)
Network Interface-DAVIC

Host Type: One-Way
FDC Status
Frequency: 74500 kHz
Data Rate: 1.544 Mbps
RS Corr Err: 0
RS Uncorr Err: 0
Status: Locked >>If the signal drops or the card can't lock this will show unlocked. If there errors they will show here as well. The Cisco system uses 74.5 MHz, Your system I think is 75 or In the general region. This signal is right In the area of channel 6 (Ntsc) if this is another filter in your line it could be an issue.

Cisco CableCARD(tm)
Copy Protection Information

Auth Status: CP Auth Received
Info for pgm index 0-5
[LTSID - PN - CCI - ERR ]
0x4 - 0x2a - 0x2 - 0x0
0x5 - 0x135 - 0x0 - 0x0
0x7 - 0x2b - 0x2 - 0x0
0x6 - 0x30 - 0x2 - 0x0
0x9 - 0x88f - 0x2 - 0x0
0x8 - 0x131 - 0x0 - 0x0

MKS Period: 600 seconds
VerifyKey Status: OK
Cisco CableCARD(tm)
Copy Protection Info Page 2

Refresh Status: OK
Refresh count: 477 >>This number will increment every 10 minutes on a Cisco system as long as the CA stream continues. If lost after 10 minutes the card stops decrypting
N_Host timeouts: 0
Sync Cnf timeouts: 0

Cisco CableCARD(tm)
Diagnostics
H/W Model: 0800, Ver: 0012
MAC Address: 00:21:BE:A2:A0:AA
SL. No: PKKWJNGPQ, Mode: MMODE
Boot Time
Fri Aug 29 2014, 5:11:38 PM GMT >>this is the time of the last boot.
Current Time
Tue Sep 2 2014, 4:18:24 AM GMT >>this is the current time in London
Free Memory: 1525 KB
Bldr Ver: 124
OS Ver: PKEY1.5.3_F.p.1101 >>>This is the cableCARD FW version Your FW will be in a different place.
Build Time: Jun 6 2013, 16:26:58
Resource Status: 00021C1F00027DBF
BFS: Received, Hub ID: 44

CP-CA Control bits: 0x00

This is part of the challenge and pairing

Jan 1 00:07:02 ocur[21]: upnp: [192.168.200.2] Action(wmdrm[4]) ProcessRegistrationChallenge success
Jan 1 00:07:03 ocur[21]: upnp: Event(security[5]): DrmPairingStatus, "Green"
Jan 1 00:07:03 ocur[21]: upnp: Event(security[4]): DrmPairingStatus, "Green"
Jan 1 00:07:03 ocur[21]: upnp: [192.168.200.2] Calling Action(wmdrm[4]) ProcessLicenseChallenge
Jan 1 00:07:03 ocur[21]: upnp: [192.168.200.2] Calling Action(wmdrm[5]) ProcessLicenseChallenge
Jan 1 00:07:05 ocur[21]: upnp: [192.168.200.2] Action(wmdrm[5]) ProcessLicenseChallenge success
Jan 1 00:07:05 ocur[21]: upnp: [192.168.200.2] Action(wmdrm[4]) ProcessLicenseChallenge success
Jan 1 00:07:05 ocur[21]: upnp: [192.168.200.2] Calling Action(wmdrm[5]) AcknowledgeLicense
Jan 1 00:07:05 ocur[21]: ocur: [5.c0a8c802] License Success Ack Received
Jan 1 00:07:05 ocur[21]: upnp: [192.168.200.2] Action(wmdrm[5]) AcknowledgeLicense success
Jan 1 00:07:05 ocur[21]: upnp: [192.168.200.2] Calling Action(wmdrm[4]) AcknowledgeLicense
Jan 1 00:07:05 ocur[21]: ocur: [4.c0a8c802] License Success Ack Received
Jan 1 00:07:05 ocur[21]: upnp: [192.168.200.2] Action(wmdrm[4]) AcknowledgeLicense success
Jan 1 00:07:05 ocur[21]: upnp: [192.168.200.2] Get(security[5]): HmsAssociationList "n5ByAAADTw5AAJKGAAAAAEiioKoHELCqSWY7OUAKrDVE9BtGyWsAprhFJC7imhJQ1GmLJgjsggEAAAAAAABBKgJvsKpJZjs5QAqsNUT0G0bJa3ExueAqA/Zek3Lxq/TOa+WEAQAAAAAAAEEqAnKwqklmOzlACqw1RPQbR
Jan 1 00:07:05 ocur[21]: upnp: [192.168.200.2] Get(security[4]): HmsAssociationList "n5ByAAADTw5AAJKGAAAAAEiioKoHELCqSWY7OUAKrDVE9BtGyWsAprhFJC7imhJQ1GmLJgjsggEAAAAAAABBKgJvsKpJZjs5QAqsNUT0G0bJa3ExueAqA/Zek3Lxq/TOa+WEAQAAAAAAAEEqAnKwqklmOzlACqw1RPQbR
Jan 1 00:07:07 ocur[21]: upnp: Event(security[1]): DrmPairingStatus, "Green"
Jan 1 00:07:07 ocur[21]: upnp: Event(security[2]): DrmPairingStatus, "Green"
Jan 1 00:07:07 ocur[21]: upnp: Event(security[3]): DrmPairingStatus, "Green"
Jan 1 00:07:07 ocur[21]: upnp: [192.168.200.2] Calling Action(wmdrm[2]) ProcessLicenseChallenge
Jan 1 00:07:07 ocur[21]: upnp: [192.168.200.2] Calling Action(wmdrm[3]) ProcessLicenseChallenge
Jan 1 00:07:07 ocur[21]: upnp: [192.168.200.2] Calling Action(wmdrm[1]) ProcessLicenseChallenge
Jan 1 00:07:11 ocur[21]: upnp: [192.168.200.2] Action(wmdrm[2]) ProcessLicenseChallenge success
Jan 1 00:07:11 ocur[21]: upnp: [192.168.200.2] Action(wmdrm[3]) ProcessLicenseChallenge success
Jan 1 00:07:11 ocur[21]: upnp: [192.168.200.2] Action(wmdrm[1]) ProcessLicenseChallenge success
Jan 1 00:07:11 ocur[21]: upnp: [192.168.200.2] Calling Action(wmdrm[2]) AcknowledgeLicense
Jan 1 00:07:11 ocur[21]: upnp: [192.168.200.2] Calling Action(wmdrm[3]) AcknowledgeLicense
Jan 1 00:07:11 ocur[21]: ocur: [3.c0a8c802] License Success Ack Received
Jan 1 00:07:11 ocur[21]: upnp: [192.168.200.2] Action(wmdrm[3]) AcknowledgeLicense success
Jan 1 00:07:11 ocur[21]: ocur: [2.c0a8c802] License Success Ack Received
Jan 1 00:07:11 ocur[21]: upnp: [192.168.200.2] Action(wmdrm[2]) AcknowledgeLicense success
Jan 1 00:07:11 ocur[21]: upnp: [192.168.200.2] Get(security[2]): HmsAssociationList "n5ByAAADTw5AAJKGAAAAAEiioKoHELCqSWY7OUAKrDVE9BtGyWsAprhFJC7imhJQ1GmLJgjsggEAAAAAAABBKgJvsKpJZjs5QAqsNUT0G0bJa3ExueAqA/Zek3Lxq/TOa+WEAQAAAAAAAEEqAnKwqklmOzlACqw1RPQbR
Jan 1 00:07:11 ocur[21]: upnp: [192.168.200.2] Get(security[3]): HmsAssociationList "n5ByAAADTw5AAJKGAAAAAEiioKoHELCqSWY7OUAKrDVE9BtGyWsAprhFJC7imhJQ1GmLJgjsggEAAAAAAABBKgJvsKpJZjs5QAqsNUT0G0bJa3ExueAqA/Zek3Lxq/TOa+WEAQAAAAAAAEEqAnKwqklmOzlACqw1RPQbR
Jan 1 00:07:11 ocur[21]: upnp: [192.168.200.2] Calling Action(wmdrm[1]) AcknowledgeLicense
Jan 1 00:07:11 ocur[21]: ocur: [1.c0a8c802] License Success Ack Received
Jan 1 00:07:11 ocur[21]: upnp: [192.168.200.2] Action(wmdrm[1]) AcknowledgeLicense success
Jan 1 00:07:11 ocur[21]: upnp: [192.168.200.2] Get(security[1]): HmsAssociationList "n5ByAAADTw5AAJKGAAAAAEiioKoHELCqSWY7OUAKrDVE9BtGyWsAprhFJC7imhJQ1GmLJgjsggEAAAAAAABBKgJvsKpJZjs5QAqsNUT0G0bJa3ExueAqA/Zek3Lxq/TOa+WEAQAAAAAAAEEqAnKwqklmOzlACqw1RPQbR
Jan 1 00:11:06 ocur[21]: ocur: WARNING: server query already in progress
Jan 1 00:11:06 ocur[21]: upnp: Event(octa[6]): UDCPMessage, "BAEAIgEABAAddHI6Ly8vZGlhZy81XzEuaHRtbDtyZWZyZXNoPVk="
Jan 1 00:11:07 ocur[21]: upnp: [192.168.200.2] Calling Action(octa[6]) SendMessageToUDCP
Jan 1 00:11:10 ocur[21]: upnp: [192.168.200.2] Action(octa[6]) SendMessageToUDCP success
Jan 1 00:11:36 ocur[21]: upnp: Event(octa[6]): UDCPMessage, "BAEAGAEABQATdHI6Ly8vZGlhZy81XzIuaHRtbA=="
Jan 1 00:11:37 ocur[21]: upnp: [192.168.200.2] Calling Action(octa[6]) SendMessageToUDCP
Jan 1 00:11:37 ocur[21]: upnp: [192.168.200.2] Action(octa[6]) SendMessageToUDCP success
Jan 1 00:11:42 ocur[21]: upnp: Event(octa[6]): UDCPMessage, "BAEAGAEABgATdHI6Ly8vZGlhZy81XzEuaHRtbA=="
Jan 1 00:11:42 ocur[21]: upnp: [192.168.200.2] Calling Action(octa[6]) SendMessageToUDCP
Jan 1 00:11:42 ocur[21]: upnp: [192.168.200.2] Action(octa[6]) SendMessageToUDCP success

bds3151 · #19

I had cable card dropouts with frequent "tuner not available" and "subscription required" messages. Did a lot of changes including replacing the cable card itself. Replaced the standard Ceton issued power supply with a 12v 3A and everything stabilized. Seems the power supplies may be marginal or there was a bad lot shipped since some users report as working ok and some have problems. If you try this, please report back if it helped.

#20

bds3151 wrote:I had cable card dropouts with frequent "tuner not available" and "subscription required" messages. Did a lot of changes including replacing the cable card itself. Replaced the standard Ceton issued power supply with a 12v 3A and everything stabilized. Seems the power supplies may be marginal or there was a bad lot shipped since some users report as working ok and some have problems. If you try this, please report back if it helped.

JohnW248 wrote:There could be a few other things to check, but they are Comcast related. If you are experiencing any problem with the OOB signal or the CA Stream, that might explain the problem as well. I don't know how the encryption scheme works on Moto systems, but on Cisco the CA stream after authorization gets updated every 10 minuets, if the OOB signal drops for a moment or there are DAVIC errors, that could cause a channel to drop.

Sorry about the radio silence, I got (and still have) the flu.

Lying in bed I watched TV on the upstairs HTPC, just to recap it has the following setup:

InfiniTV -> ZyXEL GS1100-16 -> ZyXEL GS1100-16 -> ASUS GX1005B (budget FAR 100mbit switch) - > Windows 8 HTPC

Well, to my total consternation TV worked perfectly! I didn't test multiple recordings + live TV, but channel 175 worked perfectly for hours on end, while on my other PC it dropped out in seconds.

So just to recap, the HTPC directly adjacent to the InfiniTV Eth, connected through one high end switch, runs into viewing conflicts in just a few minutes. Meanwhile, the HTPC in my bedroom, connected through three switches and several hundred feet of ethernet cables works fine!

So, what's the difference between the two setups? At first I thought it had something to do with gigabit vs 100mbit, but eventually I realised that the ASUS GX1005B does not support Energy Efficient Ethernet (802.3az). I disable EEE on my main HTPC and... everything works!

I have seen EEE mentioned in the context of debugging InfiniTV Eths. I should have tried it already.

Considering that everything else on my network works nicely I believe this must be an InfiniTV issue. Somehow, it now makes sense that low bandwidth channels (175) experience issues more rapidly than high bandwidth HD channels. This also explains your (JohnW248) comment about cheaper switches being better.

I feel like I led you guys on a wild goose chase, but we learnt a lot along the way:

Having viewing conflicts? No tuner available errors? DISABLE Energy Efficient Ethernet
The Ceton Diagnostics Utility can incorrectly report a dropped CableCARD (apparently) if you have network problems.

I haven't tested very thoroughly, so who knows I might run into more issues down the line, but so far so good.I appreciate all the help provided.

TheGreenButton - Windows Media Center Forums

TheGreenButton - Windows Media Center Forums

InfiniTV 6 ETH Comments/Issues

InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues

Re: InfiniTV 6 ETH Comments/Issues