minisatip icon indicating copy to clipboard operation
minisatip copied to clipboard

Flip-Flop pid add/del when decoding

Open lars18th opened this issue 4 years ago • 10 comments

Hi @catalinii ,

This issue has causing a lot of troubles for a long time. And now I want to describe the behaviour:

  • When you're decoding a service with a Oscam server (using a legal card), you will be in troubles if at some point the card can't decode some a small period of time.
  • In the current code when a key request fails you receive a DMX_STOP message. Check: https://github.com/catalinii/minisatip/blob/646f5bc33d4413821ea519da35b3bf603becff27/src/dvbapi.c#L269
  • This will generates the deletion of the pid with the ECM data. And this triggers inmediatly that the adapter removes this pid from the list.
  • But after 500ms you return to request the key, and then the same pid is added to the list of pids.
  • And this continues for a lot of time with a FLIP-FLOP behaviour (add-delete-add-delete-add... every 500ms).

What's the problem? That using the satipc module you're sending a lot of messages because the updating of the pid list. Generating then a huge overhead in the target SAT>IP server.

So, my request is that: Can you please provide a method to not close a pid with ecm data until a period of 1 second is passed not using it?

I feel this will solve this problem. What you think? Regards.

lars18th avatar Mar 16 '21 12:03 lars18th

Hi @catalinii ,

If I remove this check and I don't call to the del_filter() then the trouble doesn't appears: https://github.com/catalinii/minisatip/blob/646f5bc33d4413821ea519da35b3bf603becff27/src/dvbapi.c#L273 However, I think this is very tricky. So we need a most robust solution.

lars18th avatar Mar 16 '21 12:03 lars18th

Hi do you want to increase from 500ms to 1s ? or not have the behavior at all ?

catalinii avatar Mar 17 '21 04:03 catalinii

do you want to increase from 500ms to 1s ? or not have the behavior at all ?

At time I've done this modification:

  • Remove at all the block that removes the pid filter (that's the if (i < MAX_KEY_FILTERS && i >= 0)).
  • But I don't touch the next block (if (k)) that updates the last_dmx_stop value.
  • And (this is relevant) I increased the value to check inside the loop of connect_dvbapi: https://github.com/catalinii/minisatip/blob/646f5bc33d4413821ea519da35b3bf603becff27/src/dvbapi.c#L517

Without the last a race condition is created if the timeout triggers the code in the short interval between the pid is closed and reopened. And with these modifications the system seems stable.

lars18th avatar Mar 17 '21 12:03 lars18th

Hi,

Anyone experimenting some one packet not decoding error with last versions of minisatip?

Please, do this check: Open a VIDEOLAN instance and open an encrypted service using the HTTP protocol (this will garantee that no packets are missing). Then when playing the service, open the Messages Window and active Verbosity to 1. Then leave playing for around 15 minutes without stop and without using the minisatip server with any other client. You see messages like this?

ts warning: scrambled state changed on pid 100 (0->1)
ts warning: scrambled state changed on pid 100 (1->0)
ts warning: scrambled state changed on pid 101 (0->1)
ts warning: scrambled state changed on pid 101 (1->0)

And in the minisatip UI just the DEC-ERRORS: is increased for just two packets?

I see such type of erros (one packet not decoded) time to time. And I feel this has no sense. Any more with this problem?

lars18th avatar Mar 18 '21 17:03 lars18th

Hi @catalinii ,

I'm not sure if I've discovered the root cause... for both, the flip-flop in the decoding and the flip-flop in the close-open of the ecm pid. Let me to explain what I've discovered:

  • The default key expiry value (MAX_CW_TIME) is set for an obscure reason to 25 seconds. The problem with this arbitray value is that the time starts to count when you request for the key (that's when you receive the ecm). So, for example if the time for the request-answer to the keys server is around (a total) of 5 seconds, and the key starts to be active 5 seconds after, then the key will be valid for only 15 seconds. And with around of 15 seconds for in use of every key (a common value at time), then it's possible that the key expires before it will not in use. And I don't see any code to increase/update the value when the deconding starts, or a check to not invalidate it when it's active.
  • Futhermore, when you mark a key as inactive, this will ends in deleting the pid of the ecm. And this is the cause for the flip-flop problem in the close-open of the ecm pid.

My current (in testing) workaround is:

  1. Change the MAX_CW_TIME to 45 seconds, to leave sufficient time for a running key.
  2. Disable in the code described before (case DVBAPI_DMX_STOP:) what removes the ecm pid unconditionally.
  3. Increase the time to invalidate ancient keys (in the connect_dvbapi() loop) for up to 60 seconds, to only remove keys that are really unused for a lot of time (with a shorter value, the ecm pid will be closed as no check guarantees that the same ecm pid is in use by another key).

However, I'm not confortable with this workaround. I feel a more robust solution can be implemented. Any idea from you? Perhaps it will be acceptable to increase the MAX_CW_TIME, but one check of ecm pids in use before removing an invalidated key seems to be necessary. What you think?

Regards.

lars18th avatar Mar 19 '21 08:03 lars18th

Hi @catalinii ,

Please, take note that with the previous changes all my decrypting troubles have gone. However, the question is how to solve the problem definitively with a right solution. So, please comment it exposing your opinion.

Regards.

lars18th avatar Mar 19 '21 11:03 lars18th

I think there are 2 issues let's try to separate them:

  • dmx_stop
  • encrypted packets.

For the dmx stop, the behavior is if you start to send a PMT to the oscam server ehich asks for ecm pid and it cannot decrypt the packet, then it will send back dmx_stop with the ecm pid. Then minisatip stops the pmt and starts it again. I need logs to figure out why deleting the pid from thr stream fixes the problem for you.

For the decrypt issue the 25 seconds is the time from receiving the CW and is the time to start decrypting ( is fine for the CW to expire while is being used). The actual expiration may happen next time a CW is sent. Again I need logs for this -l pmt,http

catalinii avatar Mar 19 '21 16:03 catalinii

Hi @catalinii ,

dmx_stop

Your assumption is false in two aspects:

  1. The Oscam can decide to send the dmx_stop by different reasons.
  2. You close the filter when you receive the dmx_stop without checking if the emc pid is in use inside minisatip.

The visible behaviour with the current implementation, when Oscam sends this message, is a flip-flop in the opening-close of the ecm pid. So, a reasonable implementation can be then to handle the dmx_stop adding some checks. Don't you think so?

encrypted packets.

After a lot of time checking the LOGS the expiration time is not "25 seconds between the receiving of the CW and the start of the decryption". If that's your initial idea, then the code is wrong. The time starts to count when you send the ECM, and not when you receive the CW. Please, check it.

Futhermore, I feel that if a key is expired, then you invalidate it and search for another, even if it's the current active key. And this rude behaviour produces some troubles. Don't you think is preferable to check only for the expiration of a key after it can be used? So, if a key is in use, it doesn't have sense to mark it as expired. I assume that you want to delete ancient keys, but from my point of view your approach is very aggresive.

lars18th avatar Mar 19 '21 18:03 lars18th

  1. This is what I meant that the dmx_stop comes from oscam...
  2. If the pid is in use this should not happens. Again, please provide logs... as bugs are possible.

Expiry: https://github.com/catalinii/minisatip/blob/master/src/dvbapi.c#L317 https://github.com/catalinii/minisatip/blob/master/src/pmt.c#L781 -> this means 25s from the CW send time (when is actually received)

In the last versions, every CW sent for a PMT is being checked against the stream and only the CW that can decrypt the stream is used. So a key will be checked within 25s from when it is sent. If the stream is decrypted (the check passes), then the CW will continue to be used until the parity changes (or other event that can cause the CW to change happens).

Again please provide logs for this instance as well.

catalinii avatar Mar 19 '21 21:03 catalinii

Hi @catalinii ,

Thank you for your response. I feel we're in the right way to solve the issue. But please, take note before, that all (yes, ALL) decoding errors have gone with my three changes described above https://github.com/catalinii/minisatip/issues/818#issuecomment-802648576. With these three changes in the code after hours of continuous run the number of errors is ZERO. However, even if the patch works, I want to understand the cause and then fix it in the proper way. Which I'm sure you want it too.

In the last versions, every CW sent for a PMT is being checked against the stream and only the CW that can decrypt the stream is used. So a key will be checked within 25s from when it is sent.

OK. Then it's clear that now the 25 seconds start to count when the ECM request is send (and not when it's received or it's started to use). So, it's very common that these 25 seconds expire when the CW is active. Right? So, why not increase this value to a more safe value? Why you need to use a short value? What happens if you increase it to a longer value?

  1. If the pid is in use this should not happens.

This assumption about the behaviour of Oscam can be false in some circunstances. You can imagine that a pid can be active, but the internal code of Oscam can request to the tuner (dvbapi) to close the pid at any time. So if you want to continue decoding the service, as you do now, you resend the ECM request. And this as a consequence generates a new reopening of the ecm pid from Oscam. So here is the flip-flop. Take note that the Oscam code is not wrong. What the minisatip requires to handle correctly is the request to close a pid (the ecm pid) that you want to maintain active. In this case, instead of close it, you need to maintain it active in the tuner (aka the adapter), as in a very short time period (miliseconds) it will be reused. Therefore, IMHO a check before closing ecm pids is required.

If the stream is decrypted (the check passes), then the CW will continue to be used until the parity changes (or other event that can cause the CW to change happens).

As I commented before this behaviour is not true in all cases. An active CW can be disabled if the expire time occurs when the it's active. What I see is that:

  • The message DVBAPI_AOT_CA_STOP is send by you in the function keys_del(): https://github.com/catalinii/minisatip/blob/646f5bc33d4413821ea519da35b3bf603becff27/src/dvbapi.c#L724
  • This will trigger Oscam to send back a DVBAPI_DMX_STOP. And then without any check you mark the ecm pid to close: https://github.com/catalinii/minisatip/blob/646f5bc33d4413821ea519da35b3bf603becff27/src/dvbapi.c#L254
  • This event will set then the value last_dmx_stop of the CW, and the timeout loop of the function connect_dvbapi() will then removes the CW 3 seconds after: https://github.com/catalinii/minisatip/blob/646f5bc33d4413821ea519da35b3bf603becff27/src/dvbapi.c#L517

That's the current behaviour. No checks around active keys are handled. And for this reason this error appears. So, please try to revise the code. I don't feel it will be a wrong idea to: 1) Test if the key is active before calling to keys_del() (I see that this function is called at multiple points, so I can't isolate the initial trigger). 2) Don't try to remove a key until it's clear that they are unusable. With a value greater than 25 seconds, this type of problem should not occur.

Regards.

lars18th avatar Mar 20 '21 07:03 lars18th

I close this issue as the commit https://github.com/catalinii/minisatip/commit/74adf9665163b62f5f62fe210b6dff6999ccf02f resolves it.

lars18th avatar Feb 22 '23 10:02 lars18th