Hello experts…
I would appreciate if someone can answer this:
is there a way/scenario, when Drone invokes* the configuration extension more than once, for the same/single event triggered by GitHub?
*) by “invokes”, I mean sends 2 or more POST HTTP requests
If you can’t answer right away, i.e. not fully understand my question, here are more details…
Unfortunately I can’t force/replicate the scenario, but I am 100% sure the following was happening:
when I was experimenting with https://github.com/bitsbeats/drone-tree-config extension, both Drone and extension being ran in my testing environment, as local containers, I noticed that in some occasions Drone sends 2, sometimes 3 POST HTTP requests to the extension, on a single trigger from GitHub. I confirmed that by looking into container logs and also by using reverse proxy that dumps the request and response.
after that I started building my own extension where I could have more control, and again confirmed that in some cases Drone sends 2 POST http requests on a single GitHub event/trigger. I managed to take the snapshot of both of those requests and noticed that the requests are almost identical. Meaning, there is nothing new or different that Drone sends to the extension in the second request. More precisely, there is only a small difference in “build” object, like this:
first request:
{“build”: {“id”:0, … ,“version”:0}, “repo”: …}
second request:
{“build”: {“id”:11, … ,“version”:1}, “repo”: …}
I listed only the differences, everything else is the same… well, except TIMESTAMPS, which brings me to another, maybe important, point: the “created” and “updated” timestamps differ by 4-7 seconds, meaning second request is sent with that much of a time difference.
What happens next:
although the extension is invoked twice (or more), and each time it responds with a proper pipeline, Drone ends up executing only one pipeline, which is of course a good thing - it would be bad to execute the deployment multiple times. This is true for both scenarios, third party extension, and my own. Since I was able to control what my extension do, I tweaked it so it returns slightly different pipeline for the first and second request, then I confirmed: the pipeline returned as a response to the SECOND request is the one being executed by the Drone server.
As I said, “no harm done” so far, meaning only one pipeline/configuration is being executed per event/trigger; but still, I am far from comfortable pushing my extension for production use if I don’t understand the inner-workings of it and not being sure that in some future scenarios these multiple Drone-to-extension requests won’t cause some unexpected outcome.
Thanks a lot for looking into this, and feel free to ask for more details if I wasn’t able to clearly describe my issue.
Hi Nenad,
Can you share with us the runner logs for this execution where you saw this multiple HTTP requests?
Also can you share how you have configured this extension to be used and if there is any re-try logic you might have defined?
Hi Nenad,
It is normal for the extension to be invoked at least 2 times or more. Drone does not persist your yaml to local storage which means it needs to fetch on demand. First it fetches when the webhook is received to evaluate triggers. Later it fetches the yaml before sending it down to the runner. Drone 1.9.2 and higher implements in-memory caching that may result in fewer invocations, however, this is not guaranteed.
Hi,
thank you very much for your answer. Unfortunately I don’t have the logs from runner because it’s experimental local setup being restarted many times. I do have logs from 3rd party extension, from the latest “incident”, when the extension was invoked 3 times for the same trigger (see below).
Here is the configuration, I start all 3 components individually:
here is the extension log snapshot. Notice 3 times “started” and 3 times “finished” events, all within several seconds, certainly for only one trigger event:
time=“2020-11-16T17:55:44Z” level=info msg=“server listening on address :3000”
time=“2020-11-16T18:48:27Z” level=info msg=“b1b4b4b6-4bd7-42b2-b360-0efb5239c571 myOrg/kafka-transformer-transformers started”
time=“2020-11-16T18:48:27Z” level=info msg=“b1b4b4b6-4bd7-42b2-b360-0efb5239c571 match: myOrg/kafka-transformer-transformers”
time=“2020-11-16T18:48:28Z” level=debug msg=“b1b4b4b6-4bd7-42b2-b360-0efb5239c571 changed files: \n .drone.yml\n kafka-to-files/.drone.yml\n url-resolver/.drone.yml”
time=“2020-11-16T18:48:28Z” level=debug msg=“b1b4b4b6-4bd7-42b2-b360-0efb5239c571 checking myOrg/kafka-transformer-transformers .drone.yml”
time=“2020-11-16T18:48:28Z” level=info msg=“b1b4b4b6-4bd7-42b2-b360-0efb5239c571 found myOrg/kafka-transformer-transformers .drone.yml”
time=“2020-11-16T18:48:28Z” level=info msg=“b1b4b4b6-4bd7-42b2-b360-0efb5239c571 concat is disabled. Using just first .drone.yml.”
time=“2020-11-16T18:48:28Z” level=debug msg=“b1b4b4b6-4bd7-42b2-b360-0efb5239c571 checking myOrg/kafka-transformer-transformers kafka-to-files/.drone.yml”
time=“2020-11-16T18:48:28Z” level=info msg=“b1b4b4b6-4bd7-42b2-b360-0efb5239c571 found myOrg/kafka-transformer-transformers kafka-to-files/.drone.yml”
time=“2020-11-16T18:48:28Z” level=info msg=“b1b4b4b6-4bd7-42b2-b360-0efb5239c571 concat is disabled. Using just first .drone.yml.”
time=“2020-11-16T18:48:28Z” level=debug msg=“b1b4b4b6-4bd7-42b2-b360-0efb5239c571 checking myOrg/kafka-transformer-transformers url-resolver/.drone.yml”
time=“2020-11-16T18:48:28Z” level=info msg=“b1b4b4b6-4bd7-42b2-b360-0efb5239c571 found myOrg/kafka-transformer-transformers url-resolver/.drone.yml”
time=“2020-11-16T18:48:28Z” level=info msg=“b1b4b4b6-4bd7-42b2-b360-0efb5239c571 concat is disabled. Using just first .drone.yml.”
time=“2020-11-16T18:48:28Z” level=info msg=“b1b4b4b6-4bd7-42b2-b360-0efb5239c571 finished”
time=“2020-11-16T18:48:28Z” level=info msg=“32ffe9ff-53a4-45da-b316-65b0ca14b756 myOrg/kafka-transformer-transformers started”
time=“2020-11-16T18:48:28Z” level=info msg=“32ffe9ff-53a4-45da-b316-65b0ca14b756 match: myOrg/kafka-transformer-transformers”
time=“2020-11-16T18:48:28Z” level=info msg=“7c6d14af-aa41-489a-8206-69af079ff5ba myOrg/kafka-transformer-transformers started”
time=“2020-11-16T18:48:28Z” level=info msg=“7c6d14af-aa41-489a-8206-69af079ff5ba match: myOrg/kafka-transformer-transformers”
time=“2020-11-16T18:48:29Z” level=debug msg=“32ffe9ff-53a4-45da-b316-65b0ca14b756 changed files: \n .drone.yml\n kafka-to-files/.drone.yml\n url-resolver/.drone.yml”
time=“2020-11-16T18:48:29Z” level=debug msg=“32ffe9ff-53a4-45da-b316-65b0ca14b756 checking myOrg/kafka-transformer-transformers .drone.yml”
time=“2020-11-16T18:48:29Z” level=debug msg=“7c6d14af-aa41-489a-8206-69af079ff5ba changed files: \n .drone.yml\n kafka-to-files/.drone.yml\n url-resolver/.drone.yml”
time=“2020-11-16T18:48:29Z” level=debug msg=“7c6d14af-aa41-489a-8206-69af079ff5ba checking myOrg/kafka-transformer-transformers .drone.yml”
time=“2020-11-16T18:48:29Z” level=info msg=“32ffe9ff-53a4-45da-b316-65b0ca14b756 found myOrg/kafka-transformer-transformers .drone.yml”
time=“2020-11-16T18:48:29Z” level=info msg=“32ffe9ff-53a4-45da-b316-65b0ca14b756 concat is disabled. Using just first .drone.yml.”
time=“2020-11-16T18:48:29Z” level=debug msg=“32ffe9ff-53a4-45da-b316-65b0ca14b756 checking myOrg/kafka-transformer-transformers kafka-to-files/.drone.yml”
time=“2020-11-16T18:48:29Z” level=info msg=“7c6d14af-aa41-489a-8206-69af079ff5ba found myOrg/kafka-transformer-transformers .drone.yml”
time=“2020-11-16T18:48:29Z” level=info msg=“7c6d14af-aa41-489a-8206-69af079ff5ba concat is disabled. Using just first .drone.yml.”
time=“2020-11-16T18:48:29Z” level=debug msg=“7c6d14af-aa41-489a-8206-69af079ff5ba checking myOrg/kafka-transformer-transformers kafka-to-files/.drone.yml”
time=“2020-11-16T18:48:29Z” level=info msg=“32ffe9ff-53a4-45da-b316-65b0ca14b756 found myOrg/kafka-transformer-transformers kafka-to-files/.drone.yml”
time=“2020-11-16T18:48:29Z” level=info msg=“32ffe9ff-53a4-45da-b316-65b0ca14b756 concat is disabled. Using just first .drone.yml.”
time=“2020-11-16T18:48:29Z” level=debug msg=“32ffe9ff-53a4-45da-b316-65b0ca14b756 checking myOrg/kafka-transformer-transformers url-resolver/.drone.yml”
time=“2020-11-16T18:48:29Z” level=info msg=“7c6d14af-aa41-489a-8206-69af079ff5ba found myOrg/kafka-transformer-transformers kafka-to-files/.drone.yml”
time=“2020-11-16T18:48:29Z” level=info msg=“7c6d14af-aa41-489a-8206-69af079ff5ba concat is disabled. Using just first .drone.yml.”
time=“2020-11-16T18:48:29Z” level=debug msg=“7c6d14af-aa41-489a-8206-69af079ff5ba checking myOrg/kafka-transformer-transformers url-resolver/.drone.yml”
time=“2020-11-16T18:48:29Z” level=info msg=“32ffe9ff-53a4-45da-b316-65b0ca14b756 found myOrg/kafka-transformer-transformers url-resolver/.drone.yml”
time=“2020-11-16T18:48:29Z” level=info msg=“32ffe9ff-53a4-45da-b316-65b0ca14b756 concat is disabled. Using just first .drone.yml.”
time=“2020-11-16T18:48:29Z” level=info msg=“32ffe9ff-53a4-45da-b316-65b0ca14b756 finished”
time=“2020-11-16T18:48:29Z” level=info msg=“7c6d14af-aa41-489a-8206-69af079ff5ba found myOrg/kafka-transformer-transformers url-resolver/.drone.yml”
time=“2020-11-16T18:48:29Z” level=info msg=“7c6d14af-aa41-489a-8206-69af079ff5ba concat is disabled. Using just first .drone.yml.”
time=“2020-11-16T18:48:29Z” level=info msg=“7c6d14af-aa41-489a-8206-69af079ff5ba finished”
This is the pattern of calls I’ve noticed. For each webhook, it triggers
one call with BuildID: 0
multiple calls with BuildID: x
I’ve also replicated the caching in my extension, and noticed that the cache key includes the timestamps (ie CreatedAt), which are also different between the first and subsequent n-calls, ie:
the first call with BuildID: 0 is at 100000 ts
the subsequent n-calls with BuildID: x are all at 100001 ts
FWIW, I am writing a configuration extension.
First it fetches when the webhook is received to evaluate triggers. Later it fetches the yaml before sending it down to the runner.
I would think that a configuration extension would only fetch once:
Webhook received
Fetch (Find call) to extension → extension returns YAML
Evaluate triggers
Send to runners
Why would it fetch again (between step 3 and 4)? AFAIK my extension is returning the same values as it returned on step 2.
Hoping to figure this issue out as the config extension is making API calls, and as a result of this behavior, is making n-multiple redundant calls that are chewing through the rate limit.
I ended up caching based on RepoID, Event, Action, Ref, After (without Created timestamp).