Upload to Tank failed after "normalizing" stage with "504 Gateway Timeout"

changed milestone to %1.0-alpha6 — Wondrous Whale

added P1 bug labels

mentioned in issue dashboard#342 (closed)

marked this issue as related to dashboard#342 (closed)

marked this issue as related to dashboard#344

changed title from Upload to Tank failed after "normalizing" stage with "" to Upload to Tank failed after "normalizing" stage with "504 Gateway Timeout"

changed the description

added Doing label

Sorry, I cannot reproduce this problem.

I managed to upload the file, as default media source for a show and as media source for an episode. I then deleted and repeated both attempts.

I would guess this can fail in case more import jobs are running a the same time.

Keep in mind this particular import puts the one and only CPU at 100% load for six to seven minutes.

I’m closing this one for now. Feel free to reopen if the problem persists.

I've tried it multiple times again using Chrome. It always results in the same error. Now also tried with Firefox and got the error to.

There is no error indication in the log though:

Click to expand import log

.

# Datenabrufprotokoll beginnt am 4.2.2025, 12:07:04ffmpeg version 5.1.6-0+deb12u1 Copyright (c) 2000-2024 the FFmpeg developers  built with gcc 12 (Debian 12.2.0-14)  configuration: --prefix=/usr --extra-version=0+deb12u1 --toolchain=hardened --libdir=/usr/lib/x86_64-linux-gnu --incdir=/usr/include/x86_64-linux-gnu --arch=amd64 --enable-gpl --disable-stripping --enable-gnutls --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libdav1d --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libglslang --enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame --enable-libmysofa --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librabbitmq --enable-librist --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libsrt --enable-libssh --enable-libsvtav1 --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvorbis --enable-libvpx --enable-libwebp --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzimg --enable-libzmq --enable-libzvbi --enable-lv2 --enable-omx --enable-openal --enable-opencl --enable-opengl --enable-sdl2 --disable-sndio --enable-libjxl --enable-pocketsphinx --enable-librsvg --enable-libmfx --enable-libdc1394 --enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r --enable-libx264 --enable-libplacebo --enable-librav1e --enable-shared  libavutil      57. 28.100 / 57. 28.100  libavcodec     59. 37.100 / 59. 37.100  libavformat    59. 27.100 / 59. 27.100  libavdevice    59.  7.100 / 59.  7.100  libavfilter     8. 44.100 /  8. 44.100  libswscale      6.  7.100 /  6.  7.100  libswresample   4.  7.100 /  4.  7.100  libpostproc    56.  6.100 / 56.  6.100[mp3 @ 0x641817b44f00] invalid concatenated file detected - using bitrate for durationInput #0, mp3, from 'pipe:':  Metadata:    title           : Divertimento Jun 2023    genre           : Radio    artist          : Gottfried Simbriger    album           : Freirad - Divertimento    track           : 06    date            : 2023  Duration: N/A, start: 0.025057, bitrate: 194 kb/s  Stream #0:0: Audio: mp3, 44100 Hz, stereo, fltp, 194 kb/s    Metadata:      encoder         : LAME3.100Stream mapping:  Stream #0:0 -> #0:0 (mp3 (mp3float) -> pcm_s24le (native))  Stream #0:0 -> #1:0 (mp3 (mp3float) -> pcm_s16le (native))Output #0, wav, to '/srv/import-temp/tank-job-2830237111/source':  Metadata:    INAM            : Divertimento Jun 2023    IGNR            : Radio    IART            : Gottfried Simbriger    IPRD            : Freirad - Divertimento    IPRT            : 06    ICRD            : 2023    ISFT            : Lavf59.27.100  Stream #0:0: Audio: pcm_s24le ([1][0][0][0] / 0x0001), 44100 Hz, stereo, s32, 2116 kb/s    Metadata:      encoder         : Lavc59.37.100 pcm_s24leOutput #1, null, to '/dev/null':  Metadata:    encoder         : Lavf59.27.100  Stream #1:0: Audio: pcm_s16le, 192000 Hz, stereo, s16, 6144 kb/s    Metadata:      encoder         : Lavc59.37.100 pcm_s16lesize=  914767kB time=00:59:00.14 bitrate=2116.8kbits/s speed=19.9x    video:0kB audio:3569873kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown[Parsed_loudnorm_0 @ 0x641817b91700] {	"input_i" : "-17.10",	"input_tp" : "0.60",	"input_lra" : "14.00",	"input_thresh" : "-28.05",	"output_i" : "-23.97",	"output_tp" : "-6.28",	"output_lra" : "8.00",	"output_thresh" : "-34.52",	"normalization_type" : "dynamic",	"target_offset" : "-0.03"}
ffmpeg returned 0 (success)
# Normalisierungsprotokoll beginnt am 4.2.2025, 12:10:04
ffmpeg version 5.1.6-0+deb12u1 Copyright (c) 2000-2024 the FFmpeg developers  built with gcc 12 (Debian 12.2.0-14)  configuration: --prefix=/usr --extra-version=0+deb12u1 --toolchain=hardened --libdir=/usr/lib/x86_64-linux-gnu --incdir=/usr/include/x86_64-linux-gnu --arch=amd64 --enable-gpl --disable-stripping --enable-gnutls --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libdav1d --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libglslang --enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame --enable-libmysofa --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librabbitmq --enable-librist --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libsrt --enable-libssh --enable-libsvtav1 --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvorbis --enable-libvpx --enable-libwebp --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzimg --enable-libzmq --enable-libzvbi --enable-lv2 --enable-omx --enable-openal --enable-opencl --enable-opengl --enable-sdl2 --disable-sndio --enable-libjxl --enable-pocketsphinx --enable-librsvg --enable-libmfx --enable-libdc1394 --enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r --enable-libx264 --enable-libplacebo --enable-librav1e --enable-shared  libavutil      57. 28.100 / 57. 28.100  libavcodec     59. 37.100 / 59. 37.100  libavformat    59. 27.100 / 59. 27.100  libavdevice    59.  7.100 / 59.  7.100  libavfilter     8. 44.100 /  8. 44.100  libswscale      6.  7.100 /  6.  7.100  libswresample   4.  7.100 /  4.  7.100  libpostproc    56.  6.100 / 56.  6.100Input #0, wav, from 'pipe:':  Metadata:    artist          : Gottfried Simbriger    date            : 2023    genre           : Radio    title           : Divertimento Jun 2023    album           : Freirad - Divertimento    track           : 06    encoder         : Lavf59.27.100  Duration: N/A, bitrate: 2116 kb/s  Stream #0:0: Audio: pcm_s24le ([1][0][0][0] / 0x0001), 44100 Hz, stereo, s32 (24 bit), 2116 kb/sStream mapping:  Stream #0:0 -> #0:0 (pcm_s24le (native) -> flac (native))[flac @ 0x5775bab35c80] encoding as 24 bits-per-sampleOutput #0, flac, to '/srv/audio/601/48.flac':  Metadata:    artist          : Gottfried Simbriger    date            : 2023    genre           : Radio    title           : Divertimento Jun 2023    album           : Freirad - Divertimento    TRACKNUMBER     : 06    encoder         : Lavf59.27.100  Stream #0:0: Audio: flac, 44100 Hz, stereo, s32 (24 bit), 128 kb/s    Metadata:      encoder         : Lavc59.37.100 flacsize=  538724kB time=00:59:00.14 bitrate=1246.6kbits/s speed=17.4x    video:0kB audio:538716kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 0.001528%[Parsed_loudnorm_0 @ 0x5775bab39680] Input Integrated:    -17.1 LUFSInput True Peak:      +0.2 dBTPInput LRA:            14.0 LUInput Threshold:     -28.0 LUFSOutput Integrated:   -24.0 LUFSOutput True Peak:     -6.3 dBTPOutput LRA:            8.0 LUOutput Threshold:    -34.5 LUFSNormalization Type:   DynamicTarget Offset:        -0.0 LUffmpeg returned 0 (success)

@eigenwijsje can you please share which Browser you have used and if there are any other tricks to get an successful upload?

closed

removed Doing label

reopened

added Cycle [1/25] label

changed the description

In all likelyness tank doesn’t respond with a 504 error (if it does, it shouldn’t). It’s more likely that the 504 Gateway timeout error is triggered by the NGINX reverse proxy. If we want to reduce the frequency of these request errors we need to adapt the NGINX configuration (probably the proxy_read_timeout configuration for the tank location). But with a polling based architecture the dashboard will always need to have handling for connection timeouts – and it does. That’s why I say that the 504 errors aren’t really our problem. Same goes for 404 errors at the same endpoint. We have handling for both in the dashboard so any permanent error is something else.

The requests are red-ish because the dev tools network panel simply colors network requests that have a status code >= 400 red-ish. That doesn’t necessarily mean that the client app doesn’t have handling for these requests.

Thank you for the analysis. Are you saying, that the problem is likely not related to Dashboard and Steering but Nginx, and therefore Jointech should take over this task? (cc @kay_jointech)

I agree with Konrad.

Looking at the filesystem, I see the file eight times, and I see see eight file entries in tanks database:

tank=# select id, created_at from files where source__uri='upload://freirad-upload-bug--2023_06_19_divertimento_2023-06.mp3' order by created_at;
 id |          created_at
----+-------------------------------
 20 | 2025-01-28 11:45:00.621939+01
 35 | 2025-01-30 10:34:56.524417+01
 42 | 2025-02-03 16:11:12.648645+01
 43 | 2025-02-03 16:20:58.235794+01
 45 | 2025-02-03 17:58:49.078649+01
 46 | 2025-02-03 18:07:01.751785+01
 47 | 2025-02-03 19:11:08.099629+01
 49 | 2025-02-04 12:18:55.146656+01
(8 rows)

But, in I only see two entries referring to these in steerings database:

steering=# select * from program_mediasource where file_id in (20, 35, 42, 43, 45, 46, 47, 49);
select * from program_mediasource where file_id in (20, 35, 42, 43, 45, 46, 47, 49);
 id  |  duration   | file_id | order | uri | media_id | licensing_id
-----+-------------+---------+-------+-----+----------+--------------
 124 | 3540.141474 |      46 |  9999 |     |       46 |
 123 | 3540.141474 |      45 |     1 |     |        5 |
(2 rows)

That would suggest that the connection gets dropped by nginx.

Thank you Ernesto! I assign the task to you @kay_jointech.

I’m not saying that there isn’t an issue with tank (or the dashboard) whatsoever. If you’re seeing an actual failed request in the dashboard media uploader then something went wrong.

What I’m saying is that it’s just highly unlikely that the 504 and 404 errors on the /tank/api/v1/files/:fileId/import endpoint have anything to do with that and I’m trying to save us some time because IMHO it takes us in the wrong direction of finding the actual culprit. The 504 and 404 errors are expected and handled because they are a necessary consequence of a polling-based architecture. There has to be a read-timeout in NGINX. We can prolong it, but it will always be there and so we will always have to have some logic in the dashboard that knows how to address it.

As expected the issue was entirely unrelated to the 504 errors:

There was a rather arbitrary default client timeout configured in the dashboard code. The dashboard simply aborted the process when the upload phase took more then 5 minutes. I’ve changed it and the upload now works for me. Please test it from your side @david.

Tested on dashboard.aura.radio and unfortunately it is still not working. Now I get different error codes:

Another try, with slightly different logs (compare GET & PATCH in contrast to the previous try).

Also noted, that before the upload failed at 100% of the normalizing stage. After your last commits, the upload fails at the beginning of the normalizing stage.

My import on dashboard.aura.radio worked yesterday, so we definitely got a new/different issue.

But the 409 is a good starting point. There’s basically only two type of requests that return 409 errors. The authentication mechanism and the flow upload endpoint. I didn’t touch the flow uploader recently, but I will investigate it in the evening.

@david I can’t reproduce this error. The upload seems to work fine for me. I’m using the exact same file. Can you share more information on what you’re doing, what browser you’ve tested (including version and operating system), and if there is anything else you’re doing simultaneously?

I'm on Ubuntu 24.04.1 LTS. Used browser versions are already in the ticket description above.

edit: I'm not doing anything simultaneously at dashboard.aura.radio. Only the browser tab might be not always focused, if that makes any difference?

On second look at the request and error messages this part might actually be a bug in tank (or at least undefined behavior).

@eigenwijsje: In the screenshot from @david you can see that the the dashboard makes a GET request to the /files/:fileId/import endpoint with a waitFor=done query. The server responds with a 404. The dashboard treats a 404 along with a waitFor=done query on this endpoint as an indication that the import job has finished, because if there is no import job for this file (hence the 404) then the import must have finished. The PATCH request that is sent afterwards modifies the files title, because that can’t be set when creating the file. Tank sending a 404 for the import query and then responding with a 409 error and the file import is not done should not happen.

The only thing that comes to mind that might explain this is a some kind of race condition. I don’t know how tank handles uploads but if upload and normalization are two different import jobs and there is a short time frame in between them with no import job running for a file then a request to the endpoint might yield a 404 even though normalization has not yet finished. Basically:

dashboard uploading to tank
dashboard waiting for import to finish
tank finishes file upload job
dashboard triggers post-import request
tank starts normalization job
tank handles dashboard post-import request, sees running normalization job and rejects it with a 409

If this description is accurate I see two things we should address:

it should be possible to set the title in the request that creates the file object (just to avoid that PATCH request that introduces a unnecessary source of errors in the file upload handling)
tank must not return a 404 on the import endpoint if another import job is scheduled to run after one of the import jobs has finished.

The status code 409 Conflict can be returned from a total of eleven errors from the Flow JS upload, the store (the database) and the importer (fetch, convert and normalize).

I never saw these errors, but from what I see above, it only gives the status code without any details to the error causing it. I’ll add the details to the responses.

it should be possible to set the title in the request that creates the file object (just to avoid that PATCH request that introduces a unnecessary source of errors in the file upload handling)

I guess we could add a description field to the file, leave the metadata untouched that we get from the file itself after the upload to avoid confusion, and add the field to the request.

tank must not return a 404 on the import endpoint if another import job is scheduled to run after one of the import jobs has finished.

Do you mean any other part of the import for this one file (format conversion, normalization)?

I can look into this.

Technically from what I remember, the whole process is one job that goes through different job states.

assigned to @kay_jointech and unassigned @eigenwijsje

mentioned in commit dashboard@e8898c23

assigned to @kmohrf and unassigned @kay_jointech

added Doing label

added Blocked label and removed Doing label

assigned to @eigenwijsje and unassigned @kmohrf

removed Blocked label

added Doing label

marked this issue as related to #87

marked this issue as related to #88

I couldn't reproduce this by myself and with @david a couple of hours ago.

I’ve created two issues for the next cycle:

I’m closing this issue.

closed

removed Doing label

Upload to Tank failed after "normalizing" stage with "504 Gateway Timeout"

Steps to Reproduce

Expected Result

Actual Result

Observations

Logs & configuration

Environment

Designs

Child items ...

Activity