Unknow bug - Video wasn't upload

[vuisme]

Sometime my bot can not upload video to Archive Group. I try to track and debug but nothing error show on exception. It's just gone and stuck at this screen and logs

I'm using celery mode. How to debug status after send video?

[BennyThink]

Is your bot busy with uploading? By default pyrogram will only upload one file at a time. You may need to adjust max_concurrent_transmissions, see here

https://github.com/tgbot-collection/ytdlbot/commit/9f9ff0a79492e43616c41208a55fe86bee6f00d2

[vuisme]

I have tried shutting down all Masters and Workers. Only tested with 1 single download link. This is full log

2023-12-22 09:20:51,179 INFO Set uid to user 0 succeeded
2023-12-22 09:20:51,181 INFO supervisord started with pid 1
2023-12-22 09:20:52,184 INFO spawned: 'worker' with pid 7
2023-12-22 09:20:52,187 INFO spawned: 'log' with pid 8
2023-12-22 09:20:52,190 INFO spawned: 'vnstat' with pid 9
2023-12-22 09:20:53,249 INFO success: log entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-12-22 09:20:53,249 INFO success: vnstat entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-12-22 09:20:57,254 INFO success: worker entered RUNNING state, process has stayed up for > than 5 seconds (startsecs)
[2023-12-22 09:21:01 base.py:454 I] Adding job tentatively -- it will be properly scheduled when the scheduler starts
[2023-12-22 09:21:01 base.py:895 I] Added job "auto_restart" to job store "default"
[2023-12-22 09:21:01 base.py:181 I] Scheduler started
/usr/local/lib/python3.11/site-packages/celery/platforms.py:829: SecurityWarning: You're running the worker with superuser privileges: this is
absolutely not recommended!

Please specify a different user using the --uid option.

User information: uid=0 euid=0 gid=0 egid=0

  warnings.warn(SecurityWarning(ROOT_DISCOURAGED.format(
Bootstrapping Celery worker now.....

 -------------- celery@euro-nudhmw v5.3.6 (emerald-rush)
--- ***** ----- 
-- ******* ---- Linux-5.15.0-1048-oracle-aarch64-with-glibc2.36 2023-12-22 09:21:04
- *** --- * --- 
- ** ---------- [config]
- ** ---------- .> app:         tasks:0xffffaf3e2290
- ** ---------- .> transport:   redis://sv1.vutn.net:6379/0
- ** ---------- .> results:     disabled://
- *** --- * --- .> concurrency: 10 (thread)
-- ******* ---- .> task events: OFF (enable -E to monitor tasks in this worker)
--- ***** ----- 
 -------------- [queues]
                .> celery           exchange=celery(direct) key=celery

[tasks]
  . tasks.audio_task
  . tasks.direct_download_task
  . tasks.image_task
  . tasks.ytdl_download_task

[2023-12-22 09:21:04,256: WARNING/MainProcess] /usr/local/lib/python3.11/site-packages/celery/worker/consumer/consumer.py:507: CPendingDeprecationWarning: The broker_connection_retry configuration setting will no longer determine
whether broker connection retries are made during startup in Celery 6.0 and above.
If you wish to retain the existing behavior for retrying connections on startup,
you should set broker_connection_retry_on_startup to True.
  warnings.warn(

[2023-12-22 09:21:05,975: INFO/MainProcess] Connected to redis://sv1.vutn.net:6379/0
[2023-12-22 09:21:05,975: WARNING/MainProcess] /usr/local/lib/python3.11/site-packages/celery/worker/consumer/consumer.py:507: CPendingDeprecationWarning: The broker_connection_retry configuration setting will no longer determine
whether broker connection retries are made during startup in Celery 6.0 and above.
If you wish to retain the existing behavior for retrying connections on startup,
you should set broker_connection_retry_on_startup to True.
  warnings.warn(

[2023-12-22 09:21:06,834: INFO/MainProcess] mingle: searching for neighbors
[2023-12-22 09:21:10,410: INFO/MainProcess] mingle: all alone
[2023-12-22 09:21:15,398: INFO/MainProcess] celery@euro-nudhmw ready.
[2023-12-22 09:21:16,702: INFO/MainProcess] Events of group {task} enabled by remote.
[2023-12-22 09:22:18,107: INFO/MainProcess] Task tasks.ytdl_download_task[a9c5f832-c69f-4c0e-99fc-c9f6af9b427f] received
[2023-12-22 09:22:18,108: INFO/MainProcess] YouTube celery tasks started for https://www.tiktok.com/@karadenizli.maceraci/video/7310627800069803270?is_from_webapp=1&sender_device=pc
[2023-12-22 09:22:18,109: CRITICAL/MainProcess] BOT IS NOT STARTED YET: Client has not been started yet
[2023-12-22 09:22:18,351: INFO/MainProcess] Start creating a new auth key on DC2
[2023-12-22 09:22:18,352: INFO/MainProcess] Connecting...
[2023-12-22 09:22:18,370: INFO/MainProcess] Connected! Production DC2 - IPv4
[2023-12-22 09:22:19,406: INFO/MainProcess] Done auth key exchange: DhGenOk
[2023-12-22 09:22:19,407: INFO/MainProcess] Disconnected
[2023-12-22 09:22:19,416: INFO/MainProcess] Connecting...
[2023-12-22 09:22:19,434: INFO/MainProcess] Connected! Production DC2 - IPv4
[2023-12-22 09:22:19,435: INFO/MainProcess] NetworkTask started
[2023-12-22 09:22:19,610: INFO/MainProcess] Session initialized: Layer 158
[2023-12-22 09:22:19,610: INFO/MainProcess] Device: CPython 3.11.7 - Pyrogram 2.0.106
[2023-12-22 09:22:19,611: INFO/MainProcess] System: Linux 5.15.0-1048-oracle (en)
[2023-12-22 09:22:19,611: INFO/MainProcess] Session started
[2023-12-22 09:22:19,612: INFO/MainProcess] PingTask started
[2023-12-22 09:22:19,672: INFO/MainProcess] PingTask stopped
[2023-12-22 09:22:19,673: INFO/MainProcess] Disconnected
[2023-12-22 09:22:19,673: INFO/MainProcess] NetworkTask stopped
[2023-12-22 09:22:19,673: INFO/MainProcess] Session stopped
[2023-12-22 09:22:19,681: INFO/MainProcess] Start creating a new auth key on DC5
[2023-12-22 09:22:19,681: INFO/MainProcess] Connecting...
[2023-12-22 09:22:19,829: INFO/MainProcess] Connected! Production DC5 - IPv4
[2023-12-22 09:22:21,585: INFO/MainProcess] Done auth key exchange: DhGenOk
[2023-12-22 09:22:21,586: INFO/MainProcess] Disconnected
[2023-12-22 09:22:21,594: INFO/MainProcess] Connecting...
[2023-12-22 09:22:21,743: INFO/MainProcess] Connected! Production DC5 - IPv4
[2023-12-22 09:22:21,744: INFO/MainProcess] NetworkTask started
[2023-12-22 09:22:22,438: INFO/MainProcess] Session initialized: Layer 158
[2023-12-22 09:22:22,439: INFO/MainProcess] Device: CPython 3.11.7 - Pyrogram 2.0.106
[2023-12-22 09:22:22,439: INFO/MainProcess] System: Linux 5.15.0-1048-oracle (en)
[2023-12-22 09:22:22,439: INFO/MainProcess] Session started
[2023-12-22 09:22:22,439: INFO/MainProcess] PingTask started
[2023-12-22 09:22:22,995: INFO/MainProcess] Started 100 HandlerTasks
[2023-12-22 09:22:28,129: INFO/MainProcess] Downloading for https://www.tiktok.com/@karadenizli.maceraci/video/7310627800069803270?is_from_webapp=1&sender_device=pc with format bestvideo[ext=mp4][vcodec!*=av01][vcodec!*=vp09]+bestaudio[ext=m4a]/bestvideo+bestaudio
[2023-12-22 09:22:30,364: WARNING/MainProcess] ERROR: [TikTok] 7310627800069803270: Requested format is not available. Use --list-formats for a list of available formats
[2023-12-22 09:22:30,368: ERROR/MainProcess] Download failed for bestvideo[ext=mp4][vcodec!*=av01][vcodec!*=vp09]+bestaudio[ext=m4a]/bestvideo+bestaudio - https://www.tiktok.com/@karadenizli.maceraci/video/7310627800069803270?is_from_webapp=1&sender_device=pc, try another way
[2023-12-22 09:22:30,369: INFO/MainProcess] Downloading for https://www.tiktok.com/@karadenizli.maceraci/video/7310627800069803270?is_from_webapp=1&sender_device=pc with format bestvideo[vcodec^=avc]+bestaudio[acodec^=mp4a]/best[vcodec^=avc]/best
[2023-12-22 09:22:32,122: WARNING/MainProcess] 
[download]   0.0% of   25.97MiB at  Unknown B/s ETA Unknown
[2023-12-22 09:22:32,349: WARNING/MainProcess] 
[download]   0.0% of   25.97MiB at   13.18KiB/s ETA 33:38  
[2023-12-22 09:22:32,350: WARNING/MainProcess] 
[download]   0.0% of   25.97MiB at   30.60KiB/s ETA 14:29
[2023-12-22 09:22:32,351: WARNING/MainProcess] 
[download]   0.1% of   25.97MiB at   65.34KiB/s ETA 06:46
[2023-12-22 09:22:32,352: WARNING/MainProcess] 
[download]   0.1% of   25.97MiB at  134.44KiB/s ETA 03:17
[2023-12-22 09:22:32,353: WARNING/MainProcess] 
[download]   0.2% of   25.97MiB at  272.23KiB/s ETA 01:37
[2023-12-22 09:22:32,358: WARNING/MainProcess] 
[download]   0.5% of   25.97MiB at  536.18KiB/s ETA 00:49
[2023-12-22 09:22:32,369: WARNING/MainProcess] 
[download]   1.0% of   25.97MiB at    1.00MiB/s ETA 00:25
[2023-12-22 09:22:32,383: WARNING/MainProcess] 
[download]   1.9% of   25.97MiB at    1.90MiB/s ETA 00:13
[2023-12-22 09:22:32,400: WARNING/MainProcess] 
[download]   3.8% of   25.97MiB at    3.58MiB/s ETA 00:06
[2023-12-22 09:22:32,423: WARNING/MainProcess] 
[download]   7.7% of   25.97MiB at    6.64MiB/s ETA 00:03
[2023-12-22 09:22:32,453: WARNING/MainProcess] 
[download]  15.4% of   25.97MiB at   12.07MiB/s ETA 00:01
[2023-12-22 09:22:32,507: WARNING/MainProcess] 
[download]  30.8% of   25.97MiB at   20.77MiB/s ETA 00:00
[2023-12-22 09:22:32,535: WARNING/MainProcess] 
[download]  46.2% of   25.97MiB at   29.07MiB/s ETA 00:00
[2023-12-22 09:22:32,605: WARNING/MainProcess] 
[download]  61.6% of   25.97MiB at   33.20MiB/s ETA 00:00
[2023-12-22 09:22:32,635: WARNING/MainProcess] 
[download]  77.0% of   25.97MiB at   38.95MiB/s ETA 00:00
[2023-12-22 09:22:32,673: WARNING/MainProcess] 
[download]  92.4% of   25.97MiB at   43.48MiB/s ETA 00:00
[2023-12-22 09:22:32,690: WARNING/MainProcess] 
[download] 100.0% of   25.97MiB at   45.72MiB/s ETA 00:00
[2023-12-22 09:22:32,788: WARNING/MainProcess] 
[download] 100% of   25.97MiB in 00:00:00 at 36.19MiB/s  
[2023-12-22 09:22:32,789: WARNING/MainProcess] 

[2023-12-22 09:22:32,808: INFO/MainProcess] Downloading for https://www.tiktok.com/@karadenizli.maceraci/video/7310627800069803270?is_from_webapp=1&sender_device=pc with format None
[2023-12-22 09:22:34,420: WARNING/MainProcess] 
[download] 100% of   25.97MiB
[2023-12-22 09:22:34,421: WARNING/MainProcess] 

[2023-12-22 09:22:34,612: INFO/MainProcess] Download complete.
[2023-12-22 09:22:34,615: INFO/MainProcess] [PosixPath('/tmp/ytdl-nyuyffrc/İşveç Kütük Ocakta Doldurulmuş Dana Eti 🥩🏔❄️ #outdor #outdoorcooking #.mp4')]
[2023-12-22 09:22:35,152: INFO/MainProcess] Không có ảnh
ffmpeg version 5.1.4-0+deb12u1 Copyright (c) 2000-2023 the FFmpeg developers
  built with gcc 12 (Debian 12.2.0-14)
  configuration: --prefix=/usr --extra-version=0+deb12u1 --toolchain=hardened --libdir=/usr/lib/aarch64-linux-gnu --incdir=/usr/include/aarch64-linux-gnu --arch=arm64 --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-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
Input #0, mov,mp4,m4a,3gp,3g2,mj2, from '/tmp/ytdl-nyuyffrc/İşveç Kütük Ocakta Doldurulmuş Dana Eti 🥩🏔❄️ #outdor #outdoorcooking #.mp4':
  Metadata:
    major_brand     : isom
    minor_version   : 512
    compatible_brands: isomiso2mp41
    aigc_info       : {"aigc_label_type": 0}
    comment         : vid:v09044g40000clq914nog65rg3ght4k0
    encoder         : Lavf58.76.100
  Duration: 00:01:29.95, start: 0.000000, bitrate: 2422 kb/s
  Stream #0:0[0x1](und): Audio: aac (HE-AACv2) (mp4a / 0x6134706D), 44100 Hz, stereo, fltp, 64 kb/s (default)
    Metadata:
      handler_name    : SoundHandler
      vendor_id       : [0][0][0][0]
  Stream #0:1[0x2](und): Video: hevc (Main) (hvc1 / 0x31637668), yuv420p(tv, bt709), 1080x1920, 2349 kb/s, SAR 1:1 DAR 9:16, 60 fps, 60 tbr, 15360 tbn (default)
    Metadata:
      handler_name    : VideoHandler
      vendor_id       : [0][0][0][0]
Stream mapping:
  Stream #0:1 (hevc) -> scale:default
  scale:default -> Stream #0:0 (png)
Press [q] to stop, [?] for help
[swscaler @ 0xaaaad1bc8020] No accelerated colorspace conversion found from yuv420p to rgb24.
[swscaler @ 0xaaaad2211c80] No accelerated colorspace conversion found from yuv420p to rgb24.
    Last message repeated 2 times
Output #0, image2, to '/tmp/ytdl-nyuyffrc/4ecb676ec9584b708283d74fb72f816c-thunmnail.png':
  Metadata:
    major_brand     : isom
    minor_version   : 512
    compatible_brands: isomiso2mp41
    aigc_info       : {"aigc_label_type": 0}
    comment         : vid:v09044g40000clq914nog65rg3ght4k0
    encoder         : Lavf59.27.100
  Stream #0:0: Video: png, rgb24(pc, gbr/bt709/bt709, progressive), 1080x1920 [SAR 1:1 DAR 9:16], q=2-31, 200 kb/s, 60 fps, 60 tbn
    Metadata:
      encoder         : Lavc59.37.100 png
[image2 @ 0xaaaad1aae470] The specified filename '/tmp/ytdl-nyuyffrc/4ecb676ec9584b708283d74fb72f816c-thunmnail.png' does not contain an image sequence pattern or a pattern is invalid.
[image2 @ 0xaaaad1aae470] Use a pattern such as %03d for an image sequence or use the -update option (with -frames:v 1 if needed) to write a single image.
frame=    1 fps=0.4 q=-0.0 size=N/A time=00:00:00.01 bitrate=N/A speed=0.00628x    
frame=    1 fps=0.3 q=-0.0 Lsize=N/A time=00:00:00.01 bitrate=N/A speed=0.00576x    
video:2302kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown
[2023-12-22 09:22:44,730: WARNING/MainProcess] User 894875684 has no token, set download mode to Celery
[2023-12-22 09:22:45,414: INFO/MainProcess] Chat ID: botlogstbb
[2023-12-22 09:22:45,415: INFO/MainProcess] Cache ID: /tmp/ytdl-nyuyffrc/İşveç Kütük Ocakta Doldurulmuş Dana Eti 🥩🏔❄️ #outdor #outdoorcooking #.mp4
[2023-12-22 09:22:45,415: INFO/MainProcess] Group ID: botlogstbb
[2023-12-22 09:22:45,415: INFO/MainProcess] Sending as video
[2023-12-22 09:22:45,418: INFO/MainProcess] Connecting...
[2023-12-22 09:22:45,566: INFO/MainProcess] Connected! Production DC5 (media) - IPv4
[2023-12-22 09:22:45,567: INFO/MainProcess] NetworkTask started
[2023-12-22 09:22:46,240: INFO/MainProcess] Session initialized: Layer 158
[2023-12-22 09:22:46,240: INFO/MainProcess] Device: CPython 3.11.7 - Pyrogram 2.0.106
[2023-12-22 09:22:46,240: INFO/MainProcess] System: Linux 5.15.0-1048-oracle (en)
[2023-12-22 09:22:46,240: INFO/MainProcess] Session started
[2023-12-22 09:22:46,242: INFO/MainProcess] PingTask started

[BennyThink]

From the log there's nothing strange. Can you try to adjust PYRO_WORKERS and max_concurrent_transmissions to appropriate value? Also try to pull the latest code, measure network activity by vnstat -l or similar tools

[vuisme]

From the log there's nothing strange. Can you try to adjust PYRO_WORKERS and max_concurrent_transmissions to appropriate value? Also try to pull the latest code, measure network activity by vnstat -l or similar tools

Hi Benny. I try remove 3 line:

                progress=upload_hook,
                progress_args=(bot_msg,),
                reply_markup=markup,

on send video and it's can upload again. Maybe have a bug from crash before when select reply message or something. I will follow and update soon

[BennyThink]

Good to know. It may also because of upload_hook

[vuisme]

I'm not sure if this is the cause. But it seems that if there is any error during the upload process, the redis.update_metrics("video_success") function will not be called, leading to the following tasks being affected including restarting the workers. I tried putting redis.update_metrics("video_success") above the send commands and tracking more.

[BennyThink]

Can you try to manually trigger an error when uploading files(like switch on/off your wifi)? I am not sure if update_metrics is the case but it could be an deadlock somewhere..

[vuisme]

Can you try to manually trigger an error when uploading files(like switch on/off your wifi)? I am not sure if update_metrics is the case but it could be an deadlock somewhere..

I still get the error. really annoying. Common when restarting a worker to update a new image or using the /patch command. After that, all image and video upload tasks will not be able to be sent. Just gone. It can only be temporarily fixed by deleting 4 lines

                 progress=upload_hook,
                 progress_args=(bot_msg,),
                 reply_markup=markup,
                 **meta,

and reboot. And if I encounter the problem again later, I have to re-add these 4 lines and restart again LOL. it seems that changing the submitted function's arguments solves the task hanging problem

[BennyThink]

then most likely it's caused by progress=upload_hook, progress_args=(bot_msg,), 🫠

[SilverBull]

I don't wanna hijack this, but the bot should function in group then? I should open a different issue to understand why I can't make it work in a private group?

[vuisme]

I don't wanna hijack this, but the bot should function in group then? I should open a different issue to understand why I can't make it work in a private group?

It's should be work with command: /ytdl in a group