Sometimes the webhook doesn't contain feature values about featurehub HOT 17 CLOSED

It polls the log configuration every 30 seconds so you definitely dial it up and down.

from featurehub.

I have found two possible suspects around this, both race conditions and have been working around fixing them. One causes an actual error in the logs, one is more subtle depending if you create the environment and then set the webhook within microseconds of it later. I have added in support for fields from the OTEL baggage into the logs for this to allow cross thread tracking and delivery across the different services.

from featurehub.

Thanks for the bug report @amandam11 ! I will see if I can write a replicating test to get to the bottom of it :-)

from featurehub.

Sorry, I pushed my test which caused it to close. The commit here refers to it: d5f9058

I wrote a test that demonstrated how this happens - if you create say - a flag and an number, and then delete the number, you will see a webhook come through where the change is for a feature that is not in the list.

This is because the feature has been deleted, so it isn't in the current list, but it has changed. So it is operating "as designed", but perhaps not "how you want it to work". By the time this comes in, it has been deleted, so what would be your suggestion to achieve what it is you need?

Essentially the rule is if you have a key for a feature not in the list, its been deleted. If it is in the list it has been updated or created.

from featurehub.

I'm not sure this is the case when I had this happen, then until I did a featurehub restart then if I say kept changing the value of the flag, then I kept getting webhook notifications whereby there was no value attached for the feature.It would correctly say the name of the feature that I had changed in the featureKeys but its value wasn't given.
So in the example above I keep changing the value of INTKEY4, I keep getting notifications for featureKey saying INTKEY4 but not its value.

I have seen what you reported when a key was deleted, and that makes sense. In this case the featureKey is for INTKEY4 which is having its value changed not being deleted, but it gets into a sense where it will give me webhook notifications when I change the value of INTKEY4 but yet its not giving the values of INTKEY4. INTKEY4 is not deleted in this case.

from featurehub.

Some more details from the webhook notifications:

From the webhook notifications here is the series of webhooks I was getting, where you can see its reported many times:

10:25:16 valid webhook for change of value on INTKEY4
{"environment":{"environment":{"id":"48df9682-6de9-4562-8820-15d44059cd1f","version":8,"eInf":{"webhook.features.endpoint":"http://172.17.0.1:3000/appFeatureUpdate/MyPort/dummy/prd","webhook.features.enabled":"true"}},"oId":"8b929f46-ca76-4a62-888c-e273d685749a","pId":"4175f6fa-15ba-4db2-80e1-4e523efc5a3a","aId":"d6e94a16-bf04-4183-9200-b17537e9fb7e","fv":[{"feature":{"id":"6961554d-7134-442a-a3ed-e8dc4b9a7642","key":"INTKEY","valueType":"NUMBER","version":1},"value":{"id":"12da2d52-64e9-435f-a829-e66b564f6d01","key":"INTKEY","locked":false,"value":4,"version":2}},{"feature":{"id":"b4e6fea6-7a8a-4d05-b396-9a29b07947e4","key":"INTKEY3","valueType":"NUMBER","version":1},"value":{"id":"1dd1c9c2-f88f-414c-9b46-34ba614517a5","key":"INTKEY3","locked":false,"value":3,"version":1}},{"feature":{"id":"6703e5c0-9a94-408a-a0ad-0657ffa92a42","key":"INTKEY4","valueType":"NUMBER","version":1},"value":{"id":"0c169224-61a7-4e79-b172-45d4b1dd3084","key":"INTKEY4","locked":false,"value":4,"version":1}}],"sa":["f030a821-5aca-4ad5-b3c7-4874fe5448d2"],"action":"CREATE","c":0},"featureKeys":["INTKEY4"]}

10:25:41 nearly a valid webhook notification for delete of INTKEY, its ok it says INTKEY and that INTKEY value is not in list, that makes sense. But we can also see that as well as removing INTKEY frm the list of value it also has removed INTKEY4 as well.
{"environment":{"environment":{"id":"48df9682-6de9-4562-8820-15d44059cd1f","version":8,"eInf":{"webhook.features.endpoint":"http://172.17.0.1:3000/appFeatureUpdate/MyPort/dummy/prd","webhook.features.enabled":"true"}},"oId":"8b929f46-ca76-4a62-888c-e273d685749a","pId":"4175f6fa-15ba-4db2-80e1-4e523efc5a3a","aId":"d6e94a16-bf04-4183-9200-b17537e9fb7e","fv":[{"feature":{"id":"b4e6fea6-7a8a-4d05-b396-9a29b07947e4","key":"INTKEY3","valueType":"NUMBER","version":1},"value":{"id":"1dd1c9c2-f88f-414c-9b46-34ba614517a5","key":"INTKEY3","locked":false,"value":3,"version":1}}],"sa":["f030a821-5aca-4ad5-b3c7-4874fe5448d2"],"action":"CREATE","c":0},"featureKeys":["INTKEY"]}

10:25:47 invalid webhook notification for change of value on INTKEY4 to value 5
{"environment":{"environment":{"id":"48df9682-6de9-4562-8820-15d44059cd1f","version":8,"eInf":{"webhook.features.endpoint":"http://172.17.0.1:3000/appFeatureUpdate/MyPort/dummy/prd","webhook.features.enabled":"true"}},"oId":"8b929f46-ca76-4a62-888c-e273d685749a","pId":"4175f6fa-15ba-4db2-80e1-4e523efc5a3a","aId":"d6e94a16-bf04-4183-9200-b17537e9fb7e","fv":[{"feature":{"id":"b4e6fea6-7a8a-4d05-b396-9a29b07947e4","key":"INTKEY3","valueType":"NUMBER","version":1},"value":{"id":"1dd1c9c2-f88f-414c-9b46-34ba614517a5","key":"INTKEY3","locked":false,"value":3,"version":1}}],"sa":["f030a821-5aca-4ad5-b3c7-4874fe5448d2"],"action":"CREATE","c":0},"featureKeys":["INTKEY4"]}

10:26:58 invalid webhook notification for change of vlaue on INTKEY4 to value 6
{"environment":{"environment":{"id":"48df9682-6de9-4562-8820-15d44059cd1f","version":8,"eInf":{"webhook.features.endpoint":"http://172.17.0.1:3000/appFeatureUpdate/MyPort/dummy/prd","webhook.features.enabled":"true"}},"oId":"8b929f46-ca76-4a62-888c-e273d685749a","pId":"4175f6fa-15ba-4db2-80e1-4e523efc5a3a","aId":"d6e94a16-bf04-4183-9200-b17537e9fb7e","fv":[{"feature":{"id":"b4e6fea6-7a8a-4d05-b396-9a29b07947e4","key":"INTKEY3","valueType":"NUMBER","version":1},"value":{"id":"1dd1c9c2-f88f-414c-9b46-34ba614517a5","key":"INTKEY3","locked":false,"value":3,"version":1}}],"sa":["f030a821-5aca-4ad5-b3c7-4874fe5448d2"],"action":"CREATE","c":0},"featureKeys":["INTKEY4"]}

10:33:05 invalid webhook notification for changing vlaue of INTKEY4 to 7
{"environment":{"environment":{"id":"48df9682-6de9-4562-8820-15d44059cd1f","version":8,"eInf":{"webhook.features.endpoint":"http://172.17.0.1:3000/appFeatureUpdate/MyPort/dummy/prd","webhook.features.enabled":"true"}},"oId":"8b929f46-ca76-4a62-888c-e273d685749a","pId":"4175f6fa-15ba-4db2-80e1-4e523efc5a3a","aId":"d6e94a16-bf04-4183-9200-b17537e9fb7e","fv":[{"feature":{"id":"b4e6fea6-7a8a-4d05-b396-9a29b07947e4","key":"INTKEY3","valueType":"NUMBER","version":1},"value":{"id":"1dd1c9c2-f88f-414c-9b46-34ba614517a5","key":"INTKEY3","locked":false,"value":3,"version":1}}],"sa":["f030a821-5aca-4ad5-b3c7-4874fe5448d2"],"action":"CREATE","c":0},"featureKeys":["INTKEY4"]}

As you can see INTKEY4 is repeatedly reported withouts its value - so its not just the one webhook notification for the delete that is reported with no value. In the log above there is 1 webhook notificatoin for INTKEY4 with a value, and then 3 separate ones whereby INTKEY4 is the featureKey but its value isn't given. These are before I delete it.

Its not normally like this, but occassionally its get itself into this state. I'm not sure what combination or timing gets it to go into this state, but those webhook notifications for INTKEY4 are all for change of values not delete (and I can match those up with the audit entries where I can see the value change at the time, e.g.

{"@timestamp":"2023-06-22T10:33:05.536+0000","message":"{\"ts\":1687429985535,\"change\":\"U\",\"type\":\"DbFeatureValue\",\"id\":\"0c169224-61a7-4e79-b172-45d4b1dd3084\",\"data\":{\"defaultValue\":\"7\",\"version\":4,\"whenUpdated\":\"2023-06-22T10:33:05.534\"},\"oldData\":{\"defaultValue\":\"6\",\"version\":3,\"whenUpdated\":\"2023-06-22T10:26:58.600\"}}","priority":"INFO","path":"io.ebean.ChangeLog","thread":"ebean-db45","host":"featurehub","user":{"email":"<email>","id":"c8525978-d057-44f5-9521-0735b21171b1"}}

from featurehub.

Hiya Amanda, so could you give me the steps to try and repeat this in the tests?

I think if I create four int values, and then set int4 and then delete int1 and then change the value of int4 this should trigger the problem?

When you say "delete it" do you mean set the feature value to null or actually delete the feature? Also how are you doing this? Via the API or via the UI? If via the API, how are you doing it?

There is a effect in the API that if you don't pass a value on a couple of the APIs, it deletes the feature from the environment, which we have removed in 1.6.2, which is why I'm asking.

from featurehub.

1.6.2-RC is in dockerhub FWIW - it has the new field you wanted and a history API. It has a number of database changes as well that we would appreciate if you could test, but make sure you backup your database first!

https://github.com/featurehub-io/featurehub/blob/main/infra/api-bucket/files/webhooks/1.1.2.yaml#L174
https://github.com/featurehub-io/featurehub/blob/main/infra/api-bucket/files/mrapi/1.1.11.yaml#L2950

from featurehub.

Unfortunately I can't get a repeated set of steps that reliably gets it into a messed up state. I tried repeating similarly steps today and it worked fine. And I tried to do that on Friday before I raised the issue, but I couldn't get it to go into a bad state.

I've seen it get itself into this mess at least 3 times. I'm basically testing my webhook handler with a local featurehub, so I'm adding/deleting/locking/changing value/unsetting value etc on feature flags on all types - and then very occassionally it seems to get itself into a twist.

But when I try and repeat the last few steps then it doesn't reproduce the problem, and it doesn't seem to be the same sequence each time. So unfortunately I think if you do the same steps you mention it probably won't reproduce.

So I'm not sure if its timing related, but unfortunately I've not managed to get a repeatable set of simple instructions that get the system to go into this state. I tried to get the set of sequences, but of course when I kept a record of everything I'd done since restarting featurehub to get it out of the messed state, then it just worked correctly.

All the changes on the features then I am doing via the UI, and for delete I'm actually deleting the feature.

from featurehub.

If there's any debugging you would like me to do when it does get into a bad state, that would help then let me know, and I can try and collect it if it happens again. It's happened to me at least 3 times last week (this is just with featurehub running locally on my machine), whilst I've been testing my webhook notification receiver.
So there is just me changing values through the UI, and I'm just testing with one application., and don't even have any listeners running - just my webhook receiver.

from featurehub.

Given you are running the party server... Can you make a request for that environment's feature values - and are they correct or are they messed up? i.e is it just the webhook that is a problem or is the cache corrupted?

And you are just running a single party server on your own local machine right?

You can update the logging? If you get the cache to talk about what it is getting sent and receives then it might give us a clue as to what is going on? If you set it should tell you what it is sending - also consider io.featurehub.dacha2 and io.featurehub.db.publish

from featurehub.

When I say "make a request" like an SDK would. So curl -v /features?apiKey=

from featurehub.

Yes, Single party-server on local machine.
At the time I didn't request the environment feature's, but I can do that when I next see it.

I'm a little worried that if its timing then switching on lots of trace might stop it happening. Can we dynamically switch on tracing, or is just configurable on startup? As when it has got into this state, then it repeatedly seems to repeat the wrong values on the application, so switching on after its got into the state might give some info.

from featurehub.

I'm going to turn this one over to @IrinaSouth in our team. I have been trying to replicate it on and off all day and haven't had any luck. I am using the Sinatra example in here https://github.com/featurehub-io/featurehub/tree/main/backend/webhook-feature-update/sinatra-example to track the incoming webhooks. I have tried:

• updating an existing environment with a lot of features, adding and deleting INT type values
• deleting all of the features in a different application and then replacing them and changing values and deleting features of type INT in another application
• starting a new application completely from fresh.

I have tried closing my laptop for periods as well so hopefully Irina will have more luck!

from featurehub.

I also tried yesterday to reproduce again, but didn't manage to get it into the failure state. I am guessing there's some race condition somewhere, but I couldn't see anything unique in the logs when it did occur

from featurehub.

1.6.2-RC is in dockerhub FWIW - it has the new field you wanted and a history API. It has a number of database changes as well that we would appreciate if you could test, but make sure you backup your database first!

@rvowles I commented on #1016 for the testing I found on 1.6.2-RC.

from featurehub.

1.6.3 has now been released with all these fixes

from featurehub.