s3rius/rustus

Unexpected hook behaviors.

Closed this issue · 5 comments

Kaelten commented

I've been testing hooks for the last little while and there's a few things that are not behaving as I expected.

I'm using the webhook settings with all hooks enabled and in both of the below log segments I'm logging the additional info with this line.

f'    {payload.upload.id}: hook {hook_name}; method {payload.request.method}; is_final: {payload.upload.is_final}; is_partial: {payload.upload.is_partial};'

When doing a simple upload without concat I see the following logs:

    8f40fed6-4431-4ee3-8506-2e08871af41d: hook pre-create; method POST; is_final: False; is_partial: False;
INFO:     127.0.0.1:63439 - "POST /rustus/callback HTTP/1.1" 200 OK
    8f40fed6-4431-4ee3-8506-2e08871af41d: hook post-create; method POST; is_final: False; is_partial: False;
INFO:     127.0.0.1:63439 - "POST /rustus/callback HTTP/1.1" 200 OK
    8f40fed6-4431-4ee3-8506-2e08871af41d: hook post-receive; method PATCH; is_final: False; is_partial: False;
INFO:     127.0.0.1:63439 - "POST /rustus/callback HTTP/1.1" 200 OK
    8f40fed6-4431-4ee3-8506-2e08871af41d: hook post-finish; method PATCH; is_final: False; is_partial: False;
INFO:     127.0.0.1:63439 - "POST /rustus/callback HTTP/1.1" 200 OK

When doing an upload using concatenation of two parts I see this as the logs:

    dad05558-2c08-4250-aaea-8238736c7ebb: hook pre-create; method POST; is_final: False; is_partial: True;
    46c25c7d-6bfe-4486-a07e-9210cbd6f3d2: hook pre-create; method POST; is_final: False; is_partial: True;
INFO:     127.0.0.1:62958 - "POST /rustus/callback HTTP/1.1" 200 OK
INFO:     127.0.0.1:62959 - "POST /rustus/callback HTTP/1.1" 200 OK
    dad05558-2c08-4250-aaea-8238736c7ebb: hook post-create; method POST; is_final: False; is_partial: True;
INFO:     127.0.0.1:62959 - "POST /rustus/callback HTTP/1.1" 200 OK
    46c25c7d-6bfe-4486-a07e-9210cbd6f3d2: hook post-create; method POST; is_final: False; is_partial: True;
INFO:     127.0.0.1:62960 - "POST /rustus/callback HTTP/1.1" 200 OK
    dad05558-2c08-4250-aaea-8238736c7ebb: hook post-finish; method PATCH; is_final: False; is_partial: True;
    46c25c7d-6bfe-4486-a07e-9210cbd6f3d2: hook post-finish; method PATCH; is_final: False; is_partial: True;
INFO:     127.0.0.1:62960 - "POST /rustus/callback HTTP/1.1" 200 OK
INFO:     127.0.0.1:62959 - "POST /rustus/callback HTTP/1.1" 200 OK
    cf318548-2c74-4a4f-bf02-c528f248e9d5: hook pre-create; method POST; is_final: True; is_partial: False;
INFO:     127.0.0.1:62962 - "POST /rustus/callback HTTP/1.1" 200 OK
    cf318548-2c74-4a4f-bf02-c528f248e9d5: hook post-create; method POST; is_final: True; is_partial: False;
INFO:     127.0.0.1:62962 - "POST /rustus/callback HTTP/1.1" 200 OK

A few things that surprised me:

  • None of the hooks for the simple upload are labeled as is_final
  • There is only a pre-create and post-create event for the concatenation call.
  • Only the concat related events are set as is_final
  • There's no post-receive events for partial uploads

This leads me to the following thoughts, and also wondering if these are correct assumptions:

  1. Fragmented uploads (concat enabled) are identifiable by looking at the is_partial flag.
  2. To understand upload progress I'd have to look at the offset/size information provided through post_receive hooks.
  3. Since concat enabled uploads don't get post_receive hooks I can't tell what's going on with them as they upload.
  4. To understand when a upload is finished I have to look for post-create hooks that have is_final: True as well as post-finish hooks.

Is all of the above correct? Are any of the above pointing to small bugs or logic errors in how the hooks are triggered?

s3rius commented

Hi. Your observations are totally correct.

  1. is_partial and is_final flags are only used by concatenation extension. You won't find them in a simple upload workflow.
  2. Yes, you can track the progress of an upload using post-receive hooks. It sends you correct length and offset fields.
  3. You can keep track of uploads marked with "is_partial": true with post-receive hook. But the final upload is merged on the server-side, that's why you don't receive post-receive hooks. You can read overview of the concatenation extension here: https://tus.io/protocols/resumable-upload.html#concatenation.
  4. You have a good point. Maybe it would be useful to send pre-create and post-finish if it's a final upload.
Kaelten commented
  1. is_partial and is_final flags are only used by concatenation extension. You won't find them in a simple upload workflow.

Makes sense, even if semantically it'd seem like a simple upload's could benefit from the flag as well

  1. Yes, you can track the progress of an upload using post-receive hooks. It sends you correct length and offset fields.

Awesome 👍

  1. You can keep track of uploads marked with "is_partial": true with post-receive hook. But the final upload is merged on the server-side, that's why you don't receive post-receive hooks. You can read overview of the concatenation extension here: https://tus.io/protocols/resumable-upload.html#concatenation.

I think this would still make the lack of post-receive hooks for the partial chunks a form of a bug no? Looking through the logs I received pre-create, post-create, post-finish for each of the partials but no post-receive hook.

  1. You have a good point. Maybe it would be useful to send pre-create and post-finish if it's a final upload.

On this one I received a pre-create and post-create both of which work all things considered, but semantically a post-finish trigger would also make sense. This could let me disable post-create if I don't care about the information there and still know when a concatenated upload finishes successfully.

s3rius commented

Oh, I think I got you.

About lack of post-receive hooks. I wrote test server, that looks like this:

@app.post("/hooks")
def hook(
        body: dict[str, Any],
        hook_name: Optional[str] = Header(None),
):  
    print(f"{hook_name}")
    return None

And after setting up rustus I uploaded two part files in parallel and then sent a request to form the final upload.

My server logs were the following:

pre-create
INFO:     172.17.0.8:54802 - "POST /hooks HTTP/1.1" 200 OK
pre-create
INFO:     172.17.0.8:54804 - "POST /hooks HTTP/1.1" 200 OK
post-create
INFO:     172.17.0.8:54802 - "POST /hooks HTTP/1.1" 200 OK
post-create
post-finish
post-finish
pre-create
INFO:     172.17.0.8:54826 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:54840 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:54854 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:54856 - "POST /hooks HTTP/1.1" 200 OK
post-create
INFO:     172.17.0.8:54802 - "POST /hooks HTTP/1.1" 200 OK

As you can see, there is no post-receive hooks, and it's fine.

Now let's change the chunk-size to 100 bytes per request.

INFO:     Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)
pre-create
pre-create
INFO:     172.17.0.8:38276 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38286 - "POST /hooks HTTP/1.1" 200 OK
post-create
post-create
INFO:     172.17.0.8:38286 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38292 - "POST /hooks HTTP/1.1" 200 OK
post-receive
post-receive
post-receive
INFO:     172.17.0.8:38300 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38314 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38286 - "POST /hooks HTTP/1.1" 200 OK
post-receive
post-receive
post-receive
post-receive
post-receive
INFO:     172.17.0.8:38328 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38332 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38340 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38344 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38350 - "POST /hooks HTTP/1.1" 200 OK
post-receive
post-receive
post-receive
post-receive
post-receive
post-receive
post-receive
post-receive
INFO:     172.17.0.8:38358 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38366 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38398 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38382 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38416 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38402 - "POST /hooks HTTP/1.1" 200 OK
post-finish
INFO:     172.17.0.8:38428 - "POST /hooks HTTP/1.1" 200 OK
post-finish
pre-create
INFO:     172.17.0.8:38436 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38448 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38450 - "POST /hooks HTTP/1.1" 200 OK
INFO:     172.17.0.8:38458 - "POST /hooks HTTP/1.1" 200 OK
post-create
INFO:     172.17.0.8:38458 - "POST /hooks HTTP/1.1" 200 OK

🎉 Now we have post-receive hooks. 🎉

So, if your upload were fully uploaded, with only one request, you won't receive post-receive hook, but post-finish one, but if your upload can only be uploaded using multiple requests, you'll get multiple post-receive hooks.

I don't really know if sending post-receive with post-finish hook when upload finished is a great idea, since it can be misleading. But I guess I have to add note about this problem in docs.

s3rius commented

I added the note about post-finish hook in existing issue.

Kaelten commented

Ah, that makes sense now that you outline it that way. I was seeing the post-receive hook on the simple upload since my test file is big enough to require multiple chunks but small enough to not need them when it's uploading in two parallel pieces.

  • 👍1