Video download intermittently fails: "A transaction is already begun on this Session." [when testing PR #244 & 7 PRs] #271

avni · 2024-10-24T14:02:07Z

Description of bug

Video download fails initially with error, "A transaction is already begun on this Session". Subsequent downloads of same video are successful.

To Reproduce

Steps to reproduce the behavior:

Go to '/books/tasks
Click on 'Download"
Enter in a URL
In the Tasks Table, it shows the video download fails. Error is: A transaction is already begun on this Session.
Subsequent downloads of the same video succeed.

Logs

iiab-diagnostics: https://paste.centos.org/view/9bd70564
calibre-web.log https://paste.centos.org/view/643f598b (only good for one day)

Expected behavior
I expect the video download to succeed on the initial attempt.

Screenshots

Environment (please complete the following information):

OS: MacOS 14.0
Calibre-Web version: 0.6.24 Beta
Browser: Safari 17.0

holta · 2024-10-24T14:20:32Z

iiab-diagnostics: https://paste.centos.org/view/9bd70564

calibre-web.log https://paste.centos.org/view/643f598b (only good for one day)

@deldesir can you copy/paste all relevant sections from above pastebins, onto this ticket please?

(So important diagnostic material is more visible, more organized, and... is not lost!)

deldesir · 2024-10-24T23:52:37Z

IIAB diagnostics

This is: /etc/iiab/diag/8.2_ubuntu-2404_2024-10-24_09:52:45_EDT_cw-36

0. HW + SW Quick Summary

install_date = 2024-10-24T12:51:50Z   Current TZ: EDT

iiab: 1d9c0199c, 86 PR's / 273 commits since tag release-8.1
    "Merge pull request #3835 from tim-moody/zimit"
    https://github.com/iiab/iiab   branch: master

iiab-admin-console: bfa53ba, 54 PR's / 157 commits since tag v0.6.2
    "Merge pull request #590 from tim-moody/0.8.5.5-fixes"
    https://github.com/iiab/iiab-admin-console   branch: master

Ubuntu 24.04.1 LTS   trixie/sid
display-manager? inactive   Arch1: arm64   Arch2: 
box 6.8.0-45-generic #45-Ubuntu SMP PREEMPT_DYNAMIC Fri Aug 30 12:26:41 UTC 2024 aarch64
-   CPU(s): 2   Mem: 1956 Swap: 0

Filesystem      Size  Used Avail Use% Mounted on
/dev/sda1        19G  3.6G   15G  20% /      ZIMs: 0 OER2Go: 0 Apps2B: 1

lo enp0s1 enp0s2 tailscale0
box box.lan localhost localhost.localdomain
192.168.64.43 192.168.0.235 fd78:49f8:657b:17b0:5054:ff:fea6:f230 

iiab-apps-to-be-installed :
bluetooth

=IIAB==========================================================================
COMMAND: /usr/bin/ls -ltr /etc/iiab/install-flags    # IIAB install flags

total 0
-rw-r--r-- 1 root root 0 Oct 24 08:51 iiab-ansible-complete
-rw-r--r-- 1 root root 0 Oct 24 08:55 iiab-complete




1. FILES SPECIALLY REQUESTED (FROM "iiab-diagnostics PATH/FILE1 PATH/FILE2")




2. REGULAR FILES

=IIAB==========================================================================
FILE DOES NOT EXIST: /.iiab-image
=IIAB==========================================================================
-rw-r--r-- 1 root root 380 Oct 24 08:55 /etc/iiab/iiab.env

# This is a configuration file for IIAB
# It can be sourced in a shell script or read into an application
IIAB_BASE_PATH=/opt/iiab
IIAB_DIR=/opt/iiab/iiab
IIAB_RELEASE=8.2
IIAB_REVISION=0
IIAB_GATEWAY_ENABLED=False
LAN_IP=10.10.10.10
OS=ubuntu
OS_VER=ubuntu-2404
WWWROOT=/library/www/html
STAGE=9
FQDN=box.lan
IIAB_USB_LIB_SHOW_ALL=True
IIAB_WAN_DEVICE=enp0s1
IIAB_LAN_DEVICE=br0

=IIAB==========================================================================
-rw-r--r-- 1 root root 3827 Oct 24 08:55 /etc/iiab/iiab.ini


[summary]
iiab_base = /opt/iiab
iiab_dir = /opt/iiab/iiab
disk_used_a_priori = 2038251520
iiab_software_disk_usage = 1528422400
[initial]
os_ver = ubuntu-2404
distribution = Ubuntu
arch = aarch64
dpkg_arch = arm64
dpkg_foreign_arch = 
rpi_model = none
devicetree_model = none
iiab_base_ver = 8.2
iiab_remote_url = https://github.com/iiab/iiab
iiab_branch = master
iiab_commit = 1d9c0199cbea5ed4c2f291be313e1d3646cff852
iiab_recent_tag = release-8.1
install_date = 2024-10-24T12:51:50Z
[runtime]
iiab_stage = 0
iiab_base_ver = 8.2
iiab_revision = 0
iiab_remote_url = https://github.com/iiab/iiab
runtime_branch = master
runtime_commit = 1d9c0199cbea5ed4c2f291be313e1d3646cff852
iiab_recent_tag = release-8.1
runtime_date = 2024-10-24T12:51:50Z
ansible_version = 2.17.5
kernel = 6.8.0-45-generic
memory_mb = 1956
swap_mb = 0
rpi_model = none
devicetree_model = none
os_ver = ubuntu-2404
python_version = 3.12
php_version = 8.3
first_run = True
FQDN_changed = True
[sshd]
sshd_disk_usage = 155648
name = sshd
description = "Secure Shell daemon (typically implemented by openssh-server) for remote login using the 'ssh' low-level protocol."
sshd_install = True
sshd_enabled = True
sshd_port = 22
[tailscale]
tailscale_disk_usage = 79470592
name = Tailscale (VPN)
description = "Tailscale enables live/remote support by connecting machines anywhere on the Internet, using a software-defined mesh virtual private network (VPN), and optional web-based management service."
tailscale_install = True
tailscale_enabled = False
[remoteit]
remoteit_disk_usage = 712704
name = remote.it
description = "https://remote.it can help you remotely maintain an IIAB.  Some benefits include: crossing multiple NATs/firewalls using a single TCP port, without requiring router port forwarding, and reducing your network's vulnerability."
remoteit_install = True
remoteit_enabled = False
[iiab-admin]
iiab_admin_disk_usage = 8327168
name = iiab-admin
description = "Admin User"
iiab_admin_user = iiab-admin
iiab_admin_user_install = True
iiab_admin_can_sudo = True
[nginx]
nginx_disk_usage = 59559936
name = NGINX
description = "NGINX is a web server which can also be used as a reverse proxy, load balancer, mail proxy and HTTP cache."
nginx_install = True
nginx_enabled = True
[www_base]
www_base_disk_usage = 3198976
[pylibs]
pylibs_disk_usage = 24576
[usb_lib]
usb_lib_disk_usage = 565248
name = USB_LIB
description = "USB_LIB automounts Teacher Content on USB drives to /library/www/html/local_content, so students can browse it almost immediately at http://box/usb"
usb_lib_install = True
usb_lib_enabled = True
usb_lib_umask0000_for_kolibri = True
[www_options]
www_options_disk_usage = 159744
[calibre-web]
calibreweb_disk_usage = 1120038912
name = Calibre-Web
description = "Calibre-Web is a web app providing a clean interface for browsing, reading and downloading e-books."
calibreweb_install = True
calibreweb_enabled = True
calibreweb_url1 = /books
calibreweb_url2 = /libros
calibreweb_url3 = /livres
calibreweb_path = /usr/local/calibre-web-py3
calibreweb_home = /library/calibre-web
calibreweb_port = 8083
calibreweb_settings_database = app.db
[detected_network]
has_ifcfg_gw = none
prior_gateway_device = unset
dhcpcd_result = not-found
network_manager_active = False
systemd_networkd_active = True
wan_in_interfaces = False
wireless_list_1(wifi1) = not found-1
wireless_list_2(wifi2) = not found-2
num_wifi_interfaces = 0
discovered_wireless_iface = none
discovered_wired_iface = tailscale0
exclude_devices = enp0s2
num_lan_interfaces = 1
gui_static_wan = False
iiab_lan_iface = br0
iiab_wan_iface = enp0s1
can_be_ap = False
[computed_network]
iiab_wan_enabled = True
user_wan_iface = auto
iiab_wan_iface = enp0s1
iiab_lan_enabled = True
user_lan_iface = auto
iiab_lan_iface = br0
iiab_network_mode = Gateway
network_enabled = False

=IIAB==========================================================================
-rw-r--r-- 1 root root 405 Oct 24 08:51 /etc/iiab/local_vars.yml

calibreweb_install: True
calibreweb_enabled: True
nodocs: True
kolibri_install: False
kolibri_enabled: False
kiwix_install: False
kiwix_enabled: False
osm_vector_maps_install: False
awstats_install: False
awstats_enabled: False
matomo_install: False
matomo_enabled: False
captiveportal_install: False
network_install: False
network_enabled: False
admin_console_install: False
admin_console_enabled: False

=IIAB==========================================================================
-rw-r--r-- 1 root root 350 Oct 24 08:55 /etc/iiab/iiab_state.yml

# DO *NOT* MANUALLY EDIT THIS, THANKS!
# IIAB does NOT currently support uninstalling apps/services.

sshd_installed: True
tailscale_installed: True
remoteit_installed: True
iiab_admin_installed: True
nginx_installed: True
www_base_installed: True
pylibs_installed: True
usb_lib_installed: True
www_options_installed: True
calibreweb_installed: True

=IIAB==========================================================================
lrwxrwxrwx 1 root root 39 Oct  8 19:13 /etc/resolv.conf -> ../run/systemd/resolve/stub-resolv.conf

# This is /run/systemd/resolve/stub-resolv.conf managed by man:systemd-resolved(8).
# Do not edit.
#
# This file might be symlinked as /etc/resolv.conf. If you're looking at
# /etc/resolv.conf and seeing this text, you have followed the symlink.
#
# This is a dynamic resolv.conf file for connecting local clients to the
# internal DNS stub resolver of systemd-resolved. This file lists all
# configured search domains.
#
# Run "resolvectl status" to see details about the uplink DNS servers
# currently in use.
#
# Third party programs should typically not access this file directly, but only
# through the symlink at /etc/resolv.conf. To manage man:resolv.conf(5) in a
# different way, replace this symlink by a static file or a different symlink.
#
# See man:systemd-resolved.service(8) for details about the supported modes of
# operation for /etc/resolv.conf.

nameserver 127.0.0.53
options edns0 trust-ad
search .

=IIAB==========================================================================
FILE DOES NOT EXIST: /etc/network/interfaces
=IIAB==========================================================================
FILE DOES NOT EXIST: /etc/hostapd/hostapd.conf
=IIAB==========================================================================
FILE DOES NOT EXIST: /etc/wpa_supplicant/wpa_supplicant.conf
=IIAB==========================================================================
FILE DOES NOT EXIST: /library/www/html/home/menu.json



3. CONTENT OF DIRECTORIES (1-LEVEL DEEP)

=IIAB==========================================================================
DIRECTORY DOES NOT EXIST: /etc/network/interfaces.d
=IIAB==========================================================================
DIRECTORY /etc/systemd/network FILES WILL FOLLOW...IF THEY EXIST
=IIAB==========================================================================
DIRECTORY DOES NOT EXIST: /etc/NetworkManager/system-connections
=IIAB==========================================================================
DIRECTORY /etc/netplan FILES WILL FOLLOW...IF THEY EXIST
-IIAB--------------------------------------------------------------------------
-rw------- 1 root root 272 Oct 24 08:51 /etc/netplan/50-cloud-init.yaml
                        ...ITS LAST 100 LINES FOLLOW...

network:
  version: 2
  ethernets:
    default:
      match:
        macaddress: "52:54:00:a6:f2:30"
      dhcp4: true
    extra0:
      match:
        macaddress: "52:54:00:f9:4c:5d"
      optional: true
      dhcp4: true
      dhcp4-overrides:
        route-metric: 200





4. OUTPUT OF COMMANDS

=IIAB==========================================================================
COMMAND: /usr/bin/uname -a    # Linux kernel

Linux box 6.8.0-45-generic #45-Ubuntu SMP PREEMPT_DYNAMIC Fri Aug 30 12:26:41 UTC 2024 aarch64 aarch64 aarch64 GNU/Linux

=IIAB==========================================================================
COMMAND: /usr/bin/free    # RAM memory

               total        used        free      shared  buff/cache   available
Mem:         2003228      395076      211388        4460     1499032     1608152
Swap:              0           0           0

=IIAB==========================================================================
COMMAND: /usr/bin/lscpu    # CPU details

Architecture:                         aarch64
CPU op-mode(s):                       64-bit
Byte Order:                           Little Endian
CPU(s):                               2
On-line CPU(s) list:                  0,1
Vendor ID:                            0x00
BIOS Vendor ID:                       QEMU
Model name:                           -
BIOS Model name:                      virt-8.2  CPU @ 2.0GHz
BIOS CPU family:                      1
Model:                                0
Thread(s) per core:                   1
Core(s) per socket:                   2
Socket(s):                            1
Stepping:                             0x0
BogoMIPS:                             48.00
Flags:                                fp asimd evtstrm aes pmull sha1 sha2 crc32 atomics fphp asimdhp cpuid asimdrdm jscvt fcma lrcpc dcpop sha3 asimddp sha512 asimdfhm dit uscat ilrcpc flagm sb paca pacg dcpodp flagm2 frint
NUMA node(s):                         1
NUMA node0 CPU(s):                    0,1
Vulnerability Gather data sampling:   Not affected
Vulnerability Itlb multihit:          Not affected
Vulnerability L1tf:                   Not affected
Vulnerability Mds:                    Not affected
Vulnerability Meltdown:               Not affected
Vulnerability Mmio stale data:        Not affected
Vulnerability Reg file data sampling: Not affected
Vulnerability Retbleed:               Not affected
Vulnerability Spec rstack overflow:   Not affected
Vulnerability Spec store bypass:      Vulnerable
Vulnerability Spectre v1:             Mitigation; __user pointer sanitization
Vulnerability Spectre v2:             Not affected
Vulnerability Srbds:                  Not affected
Vulnerability Tsx async abort:        Not affected

=IIAB==========================================================================
COMMAND: /usr/bin/df -h    # Disk usage

Filesystem      Size  Used Avail Use% Mounted on
tmpfs           196M  1.2M  195M   1% /run
efivarfs        256K   17K  240K   7% /sys/firmware/efi/efivars
/dev/sda1        19G  3.6G   15G  20% /
tmpfs           979M     0  979M   0% /dev/shm
tmpfs           5.0M     0  5.0M   0% /run/lock
/dev/sda16      891M   58M  771M   7% /boot
/dev/sda15       98M  6.4M   92M   7% /boot/efi
tmpfs           196M   12K  196M   1% /run/user/1000

=IIAB==========================================================================
COMMAND: /usr/bin/df -ah    # Disk usage detail

Filesystem      Size  Used Avail Use% Mounted on
sysfs              0     0     0    - /sys
proc               0     0     0    - /proc
udev            944M     0  944M   0% /dev
devpts             0     0     0    - /dev/pts
tmpfs           196M  1.2M  195M   1% /run
efivarfs        256K   17K  240K   7% /sys/firmware/efi/efivars
/dev/sda1        19G  3.6G   15G  20% /
securityfs         0     0     0    - /sys/kernel/security
tmpfs           979M     0  979M   0% /dev/shm
tmpfs           5.0M     0  5.0M   0% /run/lock
cgroup2            0     0     0    - /sys/fs/cgroup
pstore             0     0     0    - /sys/fs/pstore
bpf                0     0     0    - /sys/fs/bpf
systemd-1          -     -     -    - /proc/sys/fs/binfmt_misc
hugetlbfs          0     0     0    - /dev/hugepages
mqueue             0     0     0    - /dev/mqueue
debugfs            0     0     0    - /sys/kernel/debug
tracefs            0     0     0    - /sys/kernel/tracing
fusectl            0     0     0    - /sys/fs/fuse/connections
configfs           0     0     0    - /sys/kernel/config
/dev/sda16      891M   58M  771M   7% /boot
/dev/sda15       98M  6.4M   92M   7% /boot/efi
binfmt_misc        0     0     0    - /proc/sys/fs/binfmt_misc
tmpfs           196M   12K  196M   1% /run/user/1000

=IIAB==========================================================================
COMMAND: /usr/bin/lsblk    # Partition mount points

NAME    MAJ:MIN RM  SIZE RO TYPE MOUNTPOINTS
sda       8:0    0   20G  0 disk 
├─sda1    8:1    0   19G  0 part /
├─sda15   8:15   0   99M  0 part /boot/efi
└─sda16 259:0    0  923M  0 part /boot
vda     253:0    0   54K  1 disk 

=IIAB==========================================================================
COMMAND: /usr/sbin/blkid    # Mount point details

/dev/sda16: LABEL="BOOT" UUID="d9aa3cbb-0442-4a31-8309-39aaa280a266" BLOCK_SIZE="4096" TYPE="ext4" PARTUUID="b04d0850-cf53-4a9c-9c2f-8051a9f2af1f"
/dev/sda15: LABEL_FATBOOT="UEFI" LABEL="UEFI" UUID="D320-015D" BLOCK_SIZE="512" TYPE="vfat" PARTUUID="f2f18d92-b182-4921-91ed-964c7645bc8c"
/dev/sda1: LABEL="cloudimg-rootfs" UUID="9ef2863e-8baf-483e-ba95-65d6d9ddf7d3" BLOCK_SIZE="4096" TYPE="ext4" PARTUUID="c2eb3e1e-ce1b-405b-a907-f66e75c02c68"
/dev/vda: BLOCK_SIZE="2048" LABEL="cidata" TYPE="iso9660"

=IIAB==========================================================================
-rw-r--r-- 1 root root 146 Oct  8 19:16 /etc/fstab

LABEL=cloudimg-rootfs	/	 ext4	discard,commit=30,errors=remount-ro	0 1
LABEL=BOOT	/boot	ext4	defaults	0 2
LABEL=UEFI	/boot/efi	vfat	umask=0077	0 1

=IIAB==========================================================================
COMMAND: /usr/bin/lshw -C network    # Network hardware/interfaces

  *-network:0
       description: Ethernet controller
       product: Virtio network device
       vendor: Red Hat, Inc.
       physical id: 1
       bus info: pci@0000:00:01.0
       version: 00
       width: 64 bits
       clock: 33MHz
       capabilities: bus_master cap_list rom
       configuration: driver=virtio-pci latency=0
       resources: irq:46 ioport:10c0(size=32) memory:10080000-10083fff memory:10000000-1003ffff
     *-virtio0
          description: Ethernet interface
          physical id: 0
          bus info: virtio@0
          logical name: enp0s1
          serial: 52:54:00:a6:f2:30
          capabilities: ethernet physical
          configuration: autonegotiation=off broadcast=yes driver=virtio_net driverversion=1.0.0 ip=192.168.64.43 link=yes multicast=yes
  *-network:1
       description: Ethernet controller
       product: Virtio network device
       vendor: Red Hat, Inc.
       physical id: 2
       bus info: pci@0000:00:02.0
       version: 00
       width: 64 bits
       clock: 33MHz
       capabilities: bus_master cap_list rom
       configuration: driver=virtio-pci latency=0
       resources: irq:47 ioport:10e0(size=32) memory:10084000-10087fff memory:10040000-1007ffff
     *-virtio1
          description: Ethernet interface
          physical id: 0
          bus info: virtio@1
          logical name: enp0s2
          serial: 52:54:00:f9:4c:5d
          capabilities: ethernet physical
          configuration: autonegotiation=off broadcast=yes driver=virtio_net driverversion=1.0.0 ip=192.168.0.235 link=yes multicast=yes

=IIAB==========================================================================
COMMAND: /usr/sbin/ip addr    # Network interfaces

1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host noprefixroute 
       valid_lft forever preferred_lft forever
2: enp0s1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default qlen 1000
    link/ether 52:54:00:a6:f2:30 brd ff:ff:ff:ff:ff:ff
    inet 192.168.64.43/24 metric 100 brd 192.168.64.255 scope global dynamic enp0s1
       valid_lft 82689sec preferred_lft 82689sec
    inet6 fd78:49f8:657b:17b0:5054:ff:fea6:f230/64 scope global dynamic mngtmpaddr noprefixroute 
       valid_lft 2591902sec preferred_lft 604702sec
    inet6 fe80::5054:ff:fea6:f230/64 scope link 
       valid_lft forever preferred_lft forever
3: enp0s2: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default qlen 1000
    link/ether 52:54:00:f9:4c:5d brd ff:ff:ff:ff:ff:ff
    inet 192.168.0.235/24 metric 200 brd 192.168.0.255 scope global dynamic enp0s2
       valid_lft 7092sec preferred_lft 7092sec
    inet6 fe80::5054:ff:fef9:4c5d/64 scope link 
       valid_lft forever preferred_lft forever
4: tailscale0: <POINTOPOINT,MULTICAST,NOARP,UP,LOWER_UP> mtu 1280 qdisc fq_codel state UNKNOWN group default qlen 500
    link/none 
    inet6 fe80::28ca:c239:5ef3:8e99/64 scope link stable-privacy 
       valid_lft forever preferred_lft forever

=IIAB==========================================================================
COMMAND:     # Network interfaces (old view)

COMMAND NOT FOUND: ifconfig

=IIAB==========================================================================
COMMAND: /usr/sbin/ip route    # Routing table

default via 192.168.64.1 dev enp0s1 proto dhcp src 192.168.64.43 metric 100 
default via 192.168.0.1 dev enp0s2 proto dhcp src 192.168.0.235 metric 200 
192.168.0.0/24 dev enp0s2 proto kernel scope link src 192.168.0.235 metric 200 
192.168.0.1 dev enp0s2 proto dhcp scope link src 192.168.0.235 metric 200 
192.168.64.0/24 dev enp0s1 proto kernel scope link src 192.168.64.43 metric 100 
192.168.64.1 dev enp0s1 proto dhcp scope link src 192.168.64.43 metric 100 

=IIAB==========================================================================
COMMAND:  -rn    # Routing table (old view)

COMMAND NOT FOUND: netstat -rn

=IIAB==========================================================================
COMMAND: /usr/sbin/bridge -d link    # Bridge for LAN side


=IIAB==========================================================================
COMMAND: /usr/bin/sudo netstat -natp    # Ports/Services in use


=IIAB==========================================================================
COMMAND: /usr/bin/systemctl status dnsmasq    # Is dnsmasq running?


=IIAB==========================================================================
COMMAND: /usr/bin/sudo journalctl -b 0 -u dnsmasq    # dnsmasq log

-- No entries --

=IIAB==========================================================================
COMMAND: /usr/bin/networkctl    # systemd-networkd status

IDX LINK       TYPE     OPERATIONAL SETUP
  1 lo         loopback carrier     unmanaged
  2 enp0s1     ether    routable    configured
  3 enp0s2     ether    routable    configured
  4 tailscale0 none     degraded    unmanaged

4 links listed.

=IIAB==========================================================================
COMMAND:  d    # NetworkManager status

COMMAND NOT FOUND: nmcli d

=IIAB==========================================================================
COMMAND: /usr/bin/sudo journalctl -b 0 -u networkd-dispatcher    # networkd-dispatcher log

Oct 24 08:51:03 box-20241024 systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met.

=IIAB==========================================================================
COMMAND:  list    # Are WiFi and Bluetooth interfaces blocked?

COMMAND NOT FOUND: rfkill list

=IIAB==========================================================================
COMMAND:  reg get    # Detected WiFi country code / legal frequencies

COMMAND NOT FOUND: iw reg get

=IIAB==========================================================================
COMMAND:  dev    # List wireless interfaces

COMMAND NOT FOUND: iw dev

=IIAB==========================================================================
COMMAND:  list    # List capabilities of all wireless devices

COMMAND NOT FOUND: iw list

=IIAB==========================================================================
COMMAND: /usr/bin/systemctl status hostapd    # Downstream Wi-Fi: Is hostapd running?


=IIAB==========================================================================
COMMAND: /usr/bin/ls -l /etc/wpa_supplicant    # Upstream Wi-Fi


=IIAB==========================================================================
COMMAND: /usr/bin/ps -AH    # Process hierarchy: staging of hostapd & wpa_supplicant?

    PID TTY          TIME CMD
      2 ?        00:00:00 kthreadd
      3 ?        00:00:00   pool_workqueue_release
      4 ?        00:00:00   kworker/R-rcu_g
      5 ?        00:00:00   kworker/R-rcu_p
      6 ?        00:00:00   kworker/R-slub_
      7 ?        00:00:00   kworker/R-netns
     10 ?        00:00:00   kworker/0:0H-kblockd
     12 ?        00:00:00   kworker/R-mm_pe
     13 ?        00:00:00   rcu_tasks_kthread
     14 ?        00:00:00   rcu_tasks_rude_kthread
     15 ?        00:00:00   rcu_tasks_trace_kthread
     16 ?        00:00:00   ksoftirqd/0
     17 ?        00:00:00   rcu_preempt
     18 ?        00:00:00   migration/0
     19 ?        00:00:00   idle_inject/0
     20 ?        00:00:00   cpuhp/0
     21 ?        00:00:00   cpuhp/1
     22 ?        00:00:00   idle_inject/1
     23 ?        00:00:00   migration/1
     24 ?        00:00:00   ksoftirqd/1
     26 ?        00:00:00   kworker/1:0H-events_highpri
     28 ?        00:00:00   kdevtmpfs
     29 ?        00:00:00   kworker/R-inet_
     30 ?        00:00:00   kworker/u4:1-events_unbound
     31 ?        00:00:00   kauditd
     32 ?        00:00:00   khungtaskd
     33 ?        00:00:00   oom_reaper
     34 ?        00:00:00   kworker/R-write
     35 ?        00:00:00   kcompactd0
     36 ?        00:00:00   ksmd
     37 ?        00:00:00   khugepaged
     38 ?        00:00:00   kworker/R-kinte
     39 ?        00:00:00   kworker/R-kbloc
     40 ?        00:00:00   kworker/R-blkcg
     41 ?        00:00:00   kworker/R-tpm_d
     42 ?        00:00:00   kworker/R-ata_s
     43 ?        00:00:00   kworker/R-md
     44 ?        00:00:00   kworker/R-md_bi
     45 ?        00:00:00   kworker/R-edac-
     46 ?        00:00:00   kworker/R-devfr
     47 ?        00:00:00   watchdogd
     48 ?        00:00:00   kworker/1:1H-kblockd
     49 ?        00:00:00   kswapd0
     50 ?        00:00:00   ecryptfs-kthread
     51 ?        00:00:00   kworker/R-kthro
     52 ?        00:00:00   irq/49-ACPI:Ged
     53 ?        00:00:00   kworker/R-acpi_
     55 ?        00:00:00   scsi_eh_0
     56 ?        00:00:00   kworker/R-scsi_
     58 ?        00:00:00   kworker/R-mld
     59 ?        00:00:00   kworker/R-ipv6_
     66 ?        00:00:00   kworker/R-kstrp
     68 ?        00:00:00   kworker/u5:0
     70 ?        00:00:00   kworker/0:2-events
     72 ?        00:00:00   kworker/R-charg
    100 ?        00:00:00   kworker/0:1H
    166 ?        00:00:00   kworker/R-raid5
    205 ?        00:00:01   jbd2/sda1-8
    206 ?        00:00:00   kworker/R-ext4-
    299 ?        00:00:00   kworker/R-kmpat
    300 ?        00:00:00   kworker/R-kmpat
    355 ?        00:00:00   kworker/1:4-events
    430 ?        00:00:00   jbd2/sda16-8
    431 ?        00:00:00   kworker/R-ext4-
   1141 ?        00:00:00   kworker/R-tls-s
  19733 ?        00:00:00   psimon
  25093 ?        00:00:00   psimon
  27574 ?        00:00:00   kworker/u4:2-flush-8:0
  28295 ?        00:00:00   kworker/1:0-cgroup_destroy
  28296 ?        00:00:00   kworker/u4:0-events_unbound
  28348 ?        00:00:00   kworker/0:3-cgroup_destroy
  28414 ?        00:00:00   kworker/u4:3-events_unbound
  28696 ?        00:00:00   kworker/1:1
  28697 ?        00:00:00   kworker/1:2
      1 ?        00:00:04 systemd
    279 ?        00:00:01   systemd-journal
    494 ?        00:00:00   systemd-resolve
    501 ?        00:00:00   systemd-timesyn
    658 ?        00:00:00   systemd-network
    770 ?        00:00:00   cron
    771 ?        00:00:00   dbus-daemon
    776 ?        00:00:00   polkitd
    786 ?        00:00:00   systemd-logind
    796 ?        00:00:00   udisksd
    811 ?        00:00:00   rsyslogd
    822 ?        00:00:00   unattended-upgr
    836 ttyAMA0  00:00:00   agetty
    890 tty1     00:00:00   agetty
    909 ?        00:00:00   ModemManager
    991 ?        00:00:00   sshd
    993 ?        00:00:00     sshd
   1104 ?        00:00:00       sshd
    999 ?        00:00:00   systemd
   1000 ?        00:00:00     (sd-pam)
   4580 ?        00:00:00   sshd
  26771 ?        00:00:00     sshd
  26826 ?        00:00:00       sshd
  26827 pts/0    00:00:00         bash
  27213 pts/0    00:00:00           sudo
  27214 pts/1    00:00:00             sudo
  27215 pts/1    00:00:00               bash
  29726 pts/1    00:00:00                 iiab-diagnostic
  30571 pts/1    00:00:00                   ps
   5203 ?        00:00:02   tailscaled
   6549 ?        00:00:00   demuxer
  19732 ?        00:00:00   systemd-udevd
  22327 ?        00:00:00   php-fpm8.3
  22341 ?        00:00:00     php-fpm8.3
  22342 ?        00:00:00     php-fpm8.3
  22328 ?        00:00:00   multipathd
  25198 ?        00:00:00   nginx
  25199 ?        00:00:00     nginx
  25200 ?        00:00:00     nginx
  27674 ?        00:00:06   python3
  28254 ?        00:00:01   fwupd
  28279 ?        00:00:00   gpg-agent

=IIAB==========================================================================
COMMAND: /usr/bin/dmesg | grep -i -e 80211 -e 802\.11 -e wireless -e wifi -e wlan -e broadcom -e brcm -e bcm -e realtek | head -100    # Wi-Fi firmware/driver msgs


=IIAB==========================================================================
COMMAND: /usr/bin/lspci -nn    # Devices on PCI buses

00:00.0 Host bridge [0600]: Red Hat, Inc. QEMU PCIe Host bridge [1b36:0008]
00:01.0 Ethernet controller [0200]: Red Hat, Inc. Virtio network device [1af4:1000]
00:02.0 Ethernet controller [0200]: Red Hat, Inc. Virtio network device [1af4:1000]
00:03.0 SCSI storage controller [0100]: Red Hat, Inc. Virtio SCSI [1af4:1004]
00:04.0 SCSI storage controller [0100]: Red Hat, Inc. Virtio block device [1af4:1001]

=IIAB==========================================================================
COMMAND: /usr/bin/ls -l /lib/firmware/cypress/*43430*    # RPi Zero W & 3 WiFi firmware


=IIAB==========================================================================
COMMAND: /usr/bin/ls -l /lib/firmware/cypress/*43455*    # RPi 3 B+ & 4 WiFi firmware


=IIAB==========================================================================
COMMAND: /usr/bin/env    # Environment variables

SHELL=/bin/bash
SUDO_GID=1000
SUDO_COMMAND=/bin/bash
SUDO_USER=ubuntu
PWD=/usr/local/calibre-web-py3
LOGNAME=root
_=/usr/bin/env
HOME=/root
LANG=C.UTF-8
LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=00:su=37;41:sg=30;43:ca=00:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.wim=01;31:*.swm=01;31:*.dwm=01;31:*.esd=01;31:*.avif=01;35:*.jpg=01;35:*.jpeg=01;35:*.mjpg=01;35:*.mjpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.webp=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.flac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.oga=00;36:*.opus=00;36:*.spx=00;36:*.xspf=00;36:*~=00;90:*#=00;90:*.bak=00;90:*.crdownload=00;90:*.dpkg-dist=00;90:*.dpkg-new=00;90:*.dpkg-old=00;90:*.dpkg-tmp=00;90:*.old=00;90:*.orig=00;90:*.part=00;90:*.rej=00;90:*.rpmnew=00;90:*.rpmorig=00;90:*.rpmsave=00;90:*.swp=00;90:*.tmp=00;90:*.ucf-dist=00;90:*.ucf-new=00;90:*.ucf-old=00;90:
LESSCLOSE=/usr/bin/lesspipe %s %s
TERM=xterm-256color
LESSOPEN=| /usr/bin/lesspipe %s
USER=root
SHLVL=2
XDG_DATA_DIRS=/usr/local/share:/usr/share:/var/lib/snapd/desktop
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin
SUDO_UID=1000
MAIL=/var/mail/root
OLDPWD=/root

=IIAB==========================================================================
COMMAND:  -v    # Node.js version

COMMAND NOT FOUND: node -v

=IIAB==========================================================================
COMMAND:  -v    # npm version

COMMAND NOT FOUND: npm -v

=IIAB==========================================================================
COMMAND:  --version    # kiwix-tools

COMMAND NOT FOUND: /opt/iiab/kiwix/bin/kiwix-serve --version

=IIAB==========================================================================
COMMAND: cd /usr/local/calibre-web-py3; sudo git log --graph --oneline --decorate | head -50    # Calibre-Web version

*   26cb570c (HEAD -> master) Merge branch 'deldesir-patch-31' of https://github.com/deldesir/calibre-web
|\  
| * e9c8a3f7 Let SQLAlchemy create the db
| * 8ba356dc Enhance glue_db.py
| * ff0e1dce Update constants.py with iiab-glue.db path
| * dd259fb8 Update glue_db.py
| * 38a4a187 Model iiab-glue.db
| * e3fc081c Create glue_db.py
| *   b7055b3c Merge pull request #28 from iiab/master
| |\  
* | \   f560a237 Merge branch 'deldesir-xklb-schema' of https://github.com/deldesir/calibre-web
|\ \ \  
| * | | 2a5bf65a Add rowid
| * | | e19ce8e9 Create the db for xklb
| * | | 6ae40a7f Removing composite primary keys in Caption
| * | | 8de6b9b6 Remove db creation to align with #265
| * | | be850319 Create xklb-metada.db using SQLAlchemy
| * | | 1976c21e Enhance session
| * | | b3b2c23f Remove unused code
| * | | d3cebad1 Simplify xklb db modeling
| * | | f2c76e38 Add missing relationship
| * | | e0623958 Comment stats table
| * | | 4dc4a370 Add add_book_media_mapping function
| * | | 4e1fd5db Add missing Boolean import
| * | | 58c83419 Add xklb db initialization
| * | | d5571b03 Create blank database
| * | | 2ca806ce Get book ID mapped to media ID
| * | | f96e0bd4 Define core tables for xklb db
| * | | 1df37a2c Create xb.py
* | | |   627bbb01 Merge branch 'deldesir-patch-27' of https://github.com/deldesir/calibre-web
|\ \ \ \  
| * | | | 95a0d554 Use right session
| * | | | a440c6ae Refactor download.py
| | |/ /  
| |/| |   
* | | |   2ebc620d Merge branch 'deldesir-patch-25' of https://github.com/deldesir/calibre-web
|\ \ \ \  
| * | | | 869789c8 Optimize duration variable and fix TaskDownload call
| * | | | b0ee4f53 Add small adjustment
| * | | | 45e43235 Refactor metadata_extract.py
| |/ / /  
* | | |   58908568 Merge branch 'deldesir-patch-24' of https://github.com/deldesir/calibre-web
|\ \ \ \  
| * | | | 53a01579 Fix session mismatch
| * | | | fc2d7138 Add CaptionSearcher to xb_utils.py
| * | | | ded94b26 Add MappingService class
| * | | | 80554ab5 Use the right session
| * | | | 5cd210d2 Create xb_utils.py
| |/ / /  
* | | |   8c51a3b6 Merge branch 'deldesir-patch-23' of https://github.com/deldesir/calibre-web

=IIAB==========================================================================
COMMAND: /usr/bin/sudo lb --version    # xklb version

3.0.015

=IIAB==========================================================================
COMMAND: /usr/bin/sudo yt-dlp --version    # yt-dlp version

2024.10.22

=IIAB==========================================================================
COMMAND: /usr/bin/systemctl status calibre-web    # Is Calibre-Web running?

● calibre-web.service - Calibre-Web
     Loaded: loaded (/etc/systemd/system/calibre-web.service; enabled; preset: enabled)
     Active: active (running) since Thu 2024-10-24 09:20:56 EDT; 31min ago
   Main PID: 27674 (python3)
      Tasks: 5 (limit: 2264)
     Memory: 220.6M (peak: 359.1M)
        CPU: 51.549s
     CGroup: /system.slice/calibre-web.service
             └─27674 /usr/local/calibre-web-py3/bin/python3 /usr/local/calibre-web-py3/cps.py -p /library/calibre-web/config/app.db

Oct 24 09:47:33 box python3[27674]:  LIMIT ? OFFSET ?
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,122 INFO sqlalchemy.engine.Engine [cached since 1458s ago] ('hnveeZUk6Rg', '%Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg]%', 1, 0)
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,123 INFO sqlalchemy.engine.Engine SELECT captions.rowid AS captions_rowid, captions.media_id AS captions_media_id, captions.time AS captions_time, captions.text AS captions_text
Oct 24 09:47:33 box python3[27674]: FROM captions
Oct 24 09:47:33 box python3[27674]: WHERE captions.media_id = ?
Oct 24 09:47:33 box python3[27674]:  LIMIT ? OFFSET ?
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,123 INFO sqlalchemy.engine.Engine [cached since 1458s ago] (2, 1, 0)
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,166 INFO sqlalchemy.engine.Engine UPDATE media SET path=?, webpath=? WHERE media.id = ?
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,166 INFO sqlalchemy.engine.Engine [cached since 1458s ago] ('/library/calibre-web/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020) (3)/Norah Jones - Mini Concert - Happy Birthda - Norah Jones All A Dream.mp4', 'https://www.youtube.com/watch?v=hnveeZUk6Rg&timestamp=1729777653', 2)
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,166 INFO sqlalchemy.engine.Engine COMMIT

=IIAB==========================================================================
COMMAND: /usr/bin/journalctl -u calibre-web | tail -100    # Calibre-Web systemd log

Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,658 INFO sqlalchemy.engine.Engine CREATE INDEX idx_playlists_extractor_key ON playlists (extractor_key)
Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,658 INFO sqlalchemy.engine.Engine [no key 0.00005s] ()
Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,661 INFO sqlalchemy.engine.Engine CREATE INDEX idx_playlists_time_modified ON playlists (time_modified)
Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,661 INFO sqlalchemy.engine.Engine [no key 0.00006s] ()
Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,665 INFO sqlalchemy.engine.Engine
Oct 24 09:21:15 box python3[27674]: CREATE TABLE captions (
Oct 24 09:21:15 box python3[27674]:         rowid INTEGER NOT NULL,
Oct 24 09:21:15 box python3[27674]:         media_id INTEGER,
Oct 24 09:21:15 box python3[27674]:         time INTEGER,
Oct 24 09:21:15 box python3[27674]:         text TEXT,
Oct 24 09:21:15 box python3[27674]:         PRIMARY KEY (rowid),
Oct 24 09:21:15 box python3[27674]:         FOREIGN KEY(media_id) REFERENCES media (id)
Oct 24 09:21:15 box python3[27674]: )
Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,665 INFO sqlalchemy.engine.Engine [no key 0.00007s] ()
Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,669 INFO sqlalchemy.engine.Engine CREATE INDEX idx_captions_time ON captions (time)
Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,669 INFO sqlalchemy.engine.Engine [no key 0.00005s] ()
Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,672 INFO sqlalchemy.engine.Engine CREATE INDEX idx_captions_media_id ON captions (media_id)
Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,672 INFO sqlalchemy.engine.Engine [no key 0.00005s] ()
Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,676 INFO sqlalchemy.engine.Engine COMMIT
Oct 24 09:21:15 box python3[27674]: New blank database created.
Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,677 INFO sqlalchemy.engine.Engine BEGIN (implicit)
Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,681 INFO sqlalchemy.engine.Engine SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time AS captions_time
Oct 24 09:21:15 box python3[27674]: FROM captions
Oct 24 09:21:15 box python3[27674]: WHERE captions.text LIKE ?
Oct 24 09:21:15 box python3[27674]: 2024-10-24 09:21:15,681 INFO sqlalchemy.engine.Engine [generated in 0.00011s] ('%performance%',)
Oct 24 09:21:54 box python3[27674]: 2024-10-24 09:21:54,148 INFO sqlalchemy.engine.Engine SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time AS captions_time
Oct 24 09:21:54 box python3[27674]: FROM captions
Oct 24 09:21:54 box python3[27674]: WHERE captions.text LIKE ?
Oct 24 09:21:54 box python3[27674]: 2024-10-24 09:21:54,149 INFO sqlalchemy.engine.Engine [cached since 38.47s ago] ('%performance%',)
Oct 24 09:22:15 box python3[27674]: 2024-10-24 09:22:15,858 INFO sqlalchemy.engine.Engine ROLLBACK
Oct 24 09:22:43 box python3[27674]: 2024-10-24 09:22:43,628 INFO sqlalchemy.engine.Engine BEGIN (implicit)
Oct 24 09:22:43 box python3[27674]: 2024-10-24 09:22:43,630 INFO sqlalchemy.engine.Engine SELECT media.path AS media_path, media.duration AS media_duration, media.live_status AS media_live_status
Oct 24 09:22:43 box python3[27674]: FROM media
Oct 24 09:22:43 box python3[27674]: WHERE media.path LIKE ? AND (media.error IS NULL OR media.error = ?)
Oct 24 09:22:43 box python3[27674]: 2024-10-24 09:22:43,630 INFO sqlalchemy.engine.Engine [generated in 0.00013s] ('http%', '')
Oct 24 09:22:43 box python3[27674]: 2024-10-24 09:22:43,633 INFO sqlalchemy.engine.Engine SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error
Oct 24 09:22:43 box python3[27674]: FROM media
Oct 24 09:22:43 box python3[27674]: WHERE ? LIKE (? || media.extractor_id || ?)
Oct 24 09:22:43 box python3[27674]:  LIMIT ? OFFSET ?
Oct 24 09:22:43 box python3[27674]: 2024-10-24 09:22:43,633 INFO sqlalchemy.engine.Engine [generated in 0.00014s] ('https://www.youtube.com/watch?v=6jYtRQ2tHGg', '%', '%', 1, 0)
Oct 24 09:22:43 box python3[27674]: 2024-10-24 09:22:43,634 INFO sqlalchemy.engine.Engine COMMIT
Oct 24 09:23:15 box python3[27674]: 2024-10-24 09:23:15,076 INFO sqlalchemy.engine.Engine BEGIN (implicit)
Oct 24 09:23:15 box python3[27674]: 2024-10-24 09:23:15,079 INFO sqlalchemy.engine.Engine SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error
Oct 24 09:23:15 box python3[27674]: FROM media
Oct 24 09:23:15 box python3[27674]: WHERE media.webpath = ? AND media.path NOT LIKE ?
Oct 24 09:23:15 box python3[27674]:  LIMIT ? OFFSET ?
Oct 24 09:23:15 box python3[27674]: 2024-10-24 09:23:15,079 INFO sqlalchemy.engine.Engine [generated in 0.00033s] ('https://www.youtube.com/watch?v=6jYtRQ2tHGg', 'http%', 1, 0)
Oct 24 09:23:15 box python3[27674]: 2024-10-24 09:23:15,203 INFO sqlalchemy.engine.Engine SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error
Oct 24 09:23:15 box python3[27674]: FROM media
Oct 24 09:23:15 box python3[27674]: WHERE media.extractor_id = ? AND media.path LIKE ?
Oct 24 09:23:15 box python3[27674]:  LIMIT ? OFFSET ?
Oct 24 09:23:15 box python3[27674]: 2024-10-24 09:23:15,204 INFO sqlalchemy.engine.Engine [generated in 0.00013s] ('6jYtRQ2tHGg', '%Norah Jones： Tiny Desk Concert_1.64M_[6jYtRQ2tHGg]%', 1, 0)
Oct 24 09:23:15 box python3[27674]: 2024-10-24 09:23:15,205 INFO sqlalchemy.engine.Engine SELECT captions.rowid AS captions_rowid, captions.media_id AS captions_media_id, captions.time AS captions_time, captions.text AS captions_text
Oct 24 09:23:15 box python3[27674]: FROM captions
Oct 24 09:23:15 box python3[27674]: WHERE captions.media_id = ?
Oct 24 09:23:15 box python3[27674]:  LIMIT ? OFFSET ?
Oct 24 09:23:15 box python3[27674]: 2024-10-24 09:23:15,205 INFO sqlalchemy.engine.Engine [generated in 0.00011s] (1, 1, 0)
Oct 24 09:23:15 box python3[27674]: 2024-10-24 09:23:15,322 INFO sqlalchemy.engine.Engine UPDATE media SET path=?, webpath=? WHERE media.id = ?
Oct 24 09:23:15 box python3[27674]: 2024-10-24 09:23:15,322 INFO sqlalchemy.engine.Engine [generated in 0.00012s] ('/library/calibre-web/NPR Music/Norah Jones_ Tiny Desk Concert (2)/Norah Jones_ Tiny Desk Concert - NPR Music.mp4', 'https://www.youtube.com/watch?v=6jYtRQ2tHGg&timestamp=1729776195', 1)
Oct 24 09:23:15 box python3[27674]: 2024-10-24 09:23:15,322 INFO sqlalchemy.engine.Engine COMMIT
Oct 24 09:23:53 box python3[27674]: 2024-10-24 09:23:53,489 INFO sqlalchemy.engine.Engine BEGIN (implicit)
Oct 24 09:23:53 box python3[27674]: 2024-10-24 09:23:53,490 INFO sqlalchemy.engine.Engine SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time AS captions_time
Oct 24 09:23:53 box python3[27674]: FROM captions
Oct 24 09:23:53 box python3[27674]: WHERE captions.text LIKE ?
Oct 24 09:23:53 box python3[27674]: 2024-10-24 09:23:53,490 INFO sqlalchemy.engine.Engine [cached since 157.8s ago] ('%performance%',)
Oct 24 09:24:07 box python3[27674]: 2024-10-24 09:24:07,097 INFO sqlalchemy.engine.Engine SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time AS captions_time
Oct 24 09:24:07 box python3[27674]: FROM captions
Oct 24 09:24:07 box python3[27674]: WHERE captions.text LIKE ?
Oct 24 09:24:07 box python3[27674]: 2024-10-24 09:24:07,099 INFO sqlalchemy.engine.Engine [cached since 171.4s ago] ('%sacrifice%',)
Oct 24 09:44:01 box python3[27674]: 2024-10-24 09:44:01,156 INFO sqlalchemy.engine.Engine ROLLBACK
Oct 24 09:46:46 box python3[27674]: 2024-10-24 09:46:46,804 INFO sqlalchemy.engine.Engine BEGIN (implicit)
Oct 24 09:46:46 box python3[27674]: 2024-10-24 09:46:46,805 INFO sqlalchemy.engine.Engine SELECT media.path AS media_path, media.duration AS media_duration, media.live_status AS media_live_status
Oct 24 09:46:46 box python3[27674]: FROM media
Oct 24 09:46:46 box python3[27674]: WHERE media.path LIKE ? AND (media.error IS NULL OR media.error = ?)
Oct 24 09:46:46 box python3[27674]: 2024-10-24 09:46:46,805 INFO sqlalchemy.engine.Engine [cached since 1443s ago] ('http%', '')
Oct 24 09:46:46 box python3[27674]: 2024-10-24 09:46:46,817 INFO sqlalchemy.engine.Engine SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error
Oct 24 09:46:46 box python3[27674]: FROM media
Oct 24 09:46:46 box python3[27674]: WHERE ? LIKE (? || media.extractor_id || ?)
Oct 24 09:46:46 box python3[27674]:  LIMIT ? OFFSET ?
Oct 24 09:46:46 box python3[27674]: 2024-10-24 09:46:46,817 INFO sqlalchemy.engine.Engine [cached since 1443s ago] ('https://www.youtube.com/watch?v=hnveeZUk6Rg', '%', '%', 1, 0)
Oct 24 09:46:46 box python3[27674]: 2024-10-24 09:46:46,818 INFO sqlalchemy.engine.Engine COMMIT
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,083 INFO sqlalchemy.engine.Engine BEGIN (implicit)
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,084 INFO sqlalchemy.engine.Engine SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error
Oct 24 09:47:33 box python3[27674]: FROM media
Oct 24 09:47:33 box python3[27674]: WHERE media.webpath = ? AND media.path NOT LIKE ?
Oct 24 09:47:33 box python3[27674]:  LIMIT ? OFFSET ?
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,084 INFO sqlalchemy.engine.Engine [cached since 1458s ago] ('https://www.youtube.com/watch?v=hnveeZUk6Rg', 'http%', 1, 0)
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,122 INFO sqlalchemy.engine.Engine SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error
Oct 24 09:47:33 box python3[27674]: FROM media
Oct 24 09:47:33 box python3[27674]: WHERE media.extractor_id = ? AND media.path LIKE ?
Oct 24 09:47:33 box python3[27674]:  LIMIT ? OFFSET ?
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,122 INFO sqlalchemy.engine.Engine [cached since 1458s ago] ('hnveeZUk6Rg', '%Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg]%', 1, 0)
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,123 INFO sqlalchemy.engine.Engine SELECT captions.rowid AS captions_rowid, captions.media_id AS captions_media_id, captions.time AS captions_time, captions.text AS captions_text
Oct 24 09:47:33 box python3[27674]: FROM captions
Oct 24 09:47:33 box python3[27674]: WHERE captions.media_id = ?
Oct 24 09:47:33 box python3[27674]:  LIMIT ? OFFSET ?
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,123 INFO sqlalchemy.engine.Engine [cached since 1458s ago] (2, 1, 0)
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,166 INFO sqlalchemy.engine.Engine UPDATE media SET path=?, webpath=? WHERE media.id = ?
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,166 INFO sqlalchemy.engine.Engine [cached since 1458s ago] ('/library/calibre-web/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020) (3)/Norah Jones - Mini Concert - Happy Birthda - Norah Jones All A Dream.mp4', 'https://www.youtube.com/watch?v=hnveeZUk6Rg&timestamp=1729777653', 2)
Oct 24 09:47:33 box python3[27674]: 2024-10-24 09:47:33,166 INFO sqlalchemy.engine.Engine COMMIT

=IIAB==========================================================================
-rw-r--r-- 1 root root 46113 Oct 24 09:47 /var/log/calibre-web.log
                        ...ITS LAST 100 LINES FOLLOW...

WHERE media.webpath = ? AND media.path NOT LIKE ?
 LIMIT ? OFFSET ?
[2024-10-24 09:23:15,079]  INFO {sqlalchemy.engine.Engine:1846} [generated in 0.00033s] ('https://www.youtube.com/watch?v=6jYtRQ2tHGg', 'http%', 1, 0)
[2024-10-24 09:23:15,098]  INFO {cps.editbooks:236} Received metadata request: ImmutableMultiDict([('requested_file', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4'), ('current_user_name', 'Admin'), ('media_id', '1')])
[2024-10-24 09:23:15,098]  INFO {cps.editbooks:238} Requested file: /library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4
[2024-10-24 09:23:15,098]  INFO {cps.editbooks:243} Processing file: <_io.BufferedReader name='/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4'>
[2024-10-24 09:23:15,199] DEBUG {cps.uploader:414} Temporary file: /tmp/calibre_web/0ff8266c85d75623c739fec8c600bb9f
[2024-10-24 09:23:15,203]  INFO {sqlalchemy.engine.Engine:1846} SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error 
FROM media 
WHERE media.extractor_id = ? AND media.path LIKE ?
 LIMIT ? OFFSET ?
[2024-10-24 09:23:15,204]  INFO {sqlalchemy.engine.Engine:1846} [generated in 0.00013s] ('6jYtRQ2tHGg', '%Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg]%', 1, 0)
[2024-10-24 09:23:15,205]  INFO {sqlalchemy.engine.Engine:1846} SELECT captions.rowid AS captions_rowid, captions.media_id AS captions_media_id, captions.time AS captions_time, captions.text AS captions_text 
FROM captions 
WHERE captions.media_id = ?
 LIMIT ? OFFSET ?
[2024-10-24 09:23:15,205]  INFO {sqlalchemy.engine.Engine:1846} [generated in 0.00011s] (1, 1, 0)
[2024-10-24 09:23:15,298]  WARN {py.warnings:110} /usr/local/calibre-web-py3/cps/editbooks.py:1568: SAWarning: Object of type <Books> not in session, add operation along 'Authors.books' won't proceed (This warning originated from the Session 'autoflush' process, which was invoked automatically in response to a user-initiated operation.)
  db_element = db_session.query(db_object).filter((func.lower(db_filter).ilike(add_element))).all()

[2024-10-24 09:23:15,309] DEBUG {cps.helper:536} Moving title: /tmp/calibre_web/0ff8266c85d75623c739fec8c600bb9f to /library/calibre-web/NPR Music/Norah Jones_ Tiny Desk Concert (2)
[2024-10-24 09:23:15,320]  INFO {cps.services.xb_utils:169} Mapping added: <MediaBooksMapping(media_id=1, book_id=2)>
[2024-10-24 09:23:15,321]  INFO {cps.tasks.download:149} Successfully sent the requested file to http://192.168.64.43/books/meta
[2024-10-24 09:23:15,322]  INFO {sqlalchemy.engine.Engine:1846} UPDATE media SET path=?, webpath=? WHERE media.id = ?
[2024-10-24 09:23:15,322]  INFO {sqlalchemy.engine.Engine:1846} [generated in 0.00012s] ('/library/calibre-web/NPR Music/Norah Jones_ Tiny Desk Concert (2)/Norah Jones_ Tiny Desk Concert - NPR Music.mp4', 'https://www.youtube.com/watch?v=6jYtRQ2tHGg&timestamp=1729776195', 1)
[2024-10-24 09:23:15,322]  INFO {sqlalchemy.engine.Engine:2707} COMMIT
[2024-10-24 09:23:15,324]  INFO {cps.tasks.download:164} Media entry updated in the database.
[2024-10-24 09:23:15,324]  INFO {cps.tasks.download:67} Download task for https://www.youtube.com/watch?v=6jYtRQ2tHGg completed successfully.
[2024-10-24 09:23:53,489]  INFO {sqlalchemy.engine.Engine:2701} BEGIN (implicit)
[2024-10-24 09:23:53,490]  INFO {sqlalchemy.engine.Engine:1846} SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time AS captions_time 
FROM captions 
WHERE captions.text LIKE ?
[2024-10-24 09:23:53,490]  INFO {sqlalchemy.engine.Engine:1846} [cached since 157.8s ago] ('%performance%',)
[2024-10-24 09:24:07,097]  INFO {sqlalchemy.engine.Engine:1846} SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time AS captions_time 
FROM captions 
WHERE captions.text LIKE ?
[2024-10-24 09:24:07,099]  INFO {sqlalchemy.engine.Engine:1846} [cached since 171.4s ago] ('%sacrifice%',)
[2024-10-24 09:43:58,529] DEBUG {cps.services.worker:91} Add Task for user: Admin - Metadata fetch task for https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:43:58,532]  INFO {cps.tasks.metadata_extract:150} Starting metadata extraction task for URL: https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:43:58,533] DEBUG {cps.tasks.metadata_extract:43} Executing subprocess with args: ['lb-wrapper', 'tubeadd', 'https://www.youtube.com/watch?v=hnveeZUk6Rg']
[2024-10-24 09:44:01,156]  INFO {sqlalchemy.engine.Engine:2704} ROLLBACK
[2024-10-24 09:44:01,157] ERROR {cps.tasks.metadata_extract:197} An error occurred during the metadata extraction task: A transaction is already begun on this Session.
[2024-10-24 09:46:44,456] DEBUG {cps.services.worker:91} Add Task for user: Admin - Metadata fetch task for https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:46:44,457]  INFO {cps.tasks.metadata_extract:150} Starting metadata extraction task for URL: https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:46:44,458] DEBUG {cps.tasks.metadata_extract:43} Executing subprocess with args: ['lb-wrapper', 'tubeadd', 'https://www.youtube.com/watch?v=hnveeZUk6Rg']
[2024-10-24 09:46:46,804] DEBUG {cps.services.xb_utils:58} Fetching requested URLs from the database.
[2024-10-24 09:46:46,804]  INFO {sqlalchemy.engine.Engine:2701} BEGIN (implicit)
[2024-10-24 09:46:46,805]  INFO {sqlalchemy.engine.Engine:1846} SELECT media.path AS media_path, media.duration AS media_duration, media.live_status AS media_live_status 
FROM media 
WHERE media.path LIKE ? AND (media.error IS NULL OR media.error = ?)
[2024-10-24 09:46:46,805]  INFO {sqlalchemy.engine.Engine:1846} [cached since 1443s ago] ('http%', '')
[2024-10-24 09:46:46,806]  INFO {cps.services.xb_utils:70} Fetched 1 requested URLs.
[2024-10-24 09:46:46,806] DEBUG {cps.services.xb_utils:115} Getting extractor ID for URL: https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:46:46,817]  INFO {sqlalchemy.engine.Engine:1846} SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error 
FROM media 
WHERE ? LIKE (? || media.extractor_id || ?)
 LIMIT ? OFFSET ?
[2024-10-24 09:46:46,817]  INFO {sqlalchemy.engine.Engine:1846} [cached since 1443s ago] ('https://www.youtube.com/watch?v=hnveeZUk6Rg', '%', '%', 1, 0)
[2024-10-24 09:46:46,818]  INFO {cps.services.xb_utils:121} Extractor ID found: hnveeZUk6Rg
[2024-10-24 09:46:46,818] DEBUG {cps.tasks.metadata_extract:108} Adding download tasks to the worker thread.
[2024-10-24 09:46:46,818] DEBUG {cps.services.worker:91} Add Task for user: Admin - Download task for https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:46:46,818]  INFO {cps.tasks.metadata_extract:145} Download tasks added to the worker thread.
[2024-10-24 09:46:46,818]  INFO {sqlalchemy.engine.Engine:2707} COMMIT
[2024-10-24 09:46:46,818]  INFO {cps.tasks.metadata_extract:193} Metadata extraction task for https://www.youtube.com/watch?v=hnveeZUk6Rg completed successfully.
[2024-10-24 09:46:46,819]  INFO {cps.tasks.download:40} Starting download task for URL: https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:46:46,819] DEBUG {cps.tasks.download:49} Subprocess args: ['lb-wrapper', 'dl', 'https://www.youtube.com/watch?v=hnveeZUk6Rg']
[2024-10-24 09:46:46,819] DEBUG {cps.tasks.download:79} Monitoring subprocess for download progress.
[2024-10-24 09:46:49,367] DEBUG {cps.tasks.download:99} Download progress reached 99%.
[2024-10-24 09:47:33,082] DEBUG {cps.tasks.download:120} Post-processing after download.
[2024-10-24 09:47:33,083]  INFO {sqlalchemy.engine.Engine:2701} BEGIN (implicit)
[2024-10-24 09:47:33,084]  INFO {sqlalchemy.engine.Engine:1846} SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error 
FROM media 
WHERE media.webpath = ? AND media.path NOT LIKE ?
 LIMIT ? OFFSET ?
[2024-10-24 09:47:33,084]  INFO {sqlalchemy.engine.Engine:1846} [cached since 1458s ago] ('https://www.youtube.com/watch?v=hnveeZUk6Rg', 'http%', 1, 0)
[2024-10-24 09:47:33,087]  INFO {cps.editbooks:236} Received metadata request: ImmutableMultiDict([('requested_file', '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4'), ('current_user_name', 'Admin'), ('media_id', '2')])
[2024-10-24 09:47:33,087]  INFO {cps.editbooks:238} Requested file: /library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4
[2024-10-24 09:47:33,087]  INFO {cps.editbooks:243} Processing file: <_io.BufferedReader name='/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4'>
[2024-10-24 09:47:33,119] DEBUG {cps.uploader:414} Temporary file: /tmp/calibre_web/01e7df17359db91c8ce152b991d8bac9
[2024-10-24 09:47:33,122]  INFO {sqlalchemy.engine.Engine:1846} SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error 
FROM media 
WHERE media.extractor_id = ? AND media.path LIKE ?
 LIMIT ? OFFSET ?
[2024-10-24 09:47:33,122]  INFO {sqlalchemy.engine.Engine:1846} [cached since 1458s ago] ('hnveeZUk6Rg', '%Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg]%', 1, 0)
[2024-10-24 09:47:33,123]  INFO {sqlalchemy.engine.Engine:1846} SELECT captions.rowid AS captions_rowid, captions.media_id AS captions_media_id, captions.time AS captions_time, captions.text AS captions_text 
FROM captions 
WHERE captions.media_id = ?
 LIMIT ? OFFSET ?
[2024-10-24 09:47:33,123]  INFO {sqlalchemy.engine.Engine:1846} [cached since 1458s ago] (2, 1, 0)
[2024-10-24 09:47:33,135]  WARN {py.warnings:110} /usr/local/calibre-web-py3/cps/editbooks.py:1568: SAWarning: Object of type <Books> not in session, add operation along 'Authors.books' won't proceed (This warning originated from the Session 'autoflush' process, which was invoked automatically in response to a user-initiated operation.)
  db_element = db_session.query(db_object).filter((func.lower(db_filter).ilike(add_element))).all()

[2024-10-24 09:47:33,141] DEBUG {cps.helper:536} Moving title: /tmp/calibre_web/01e7df17359db91c8ce152b991d8bac9 to /library/calibre-web/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020) (3)
[2024-10-24 09:47:33,164]  INFO {cps.services.xb_utils:169} Mapping added: <MediaBooksMapping(media_id=2, book_id=3)>
[2024-10-24 09:47:33,166]  INFO {cps.tasks.download:149} Successfully sent the requested file to http://192.168.64.43/books/meta
[2024-10-24 09:47:33,166]  INFO {sqlalchemy.engine.Engine:1846} UPDATE media SET path=?, webpath=? WHERE media.id = ?
[2024-10-24 09:47:33,166]  INFO {sqlalchemy.engine.Engine:1846} [cached since 1458s ago] ('/library/calibre-web/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020) (3)/Norah Jones - Mini Concert - Happy Birthda - Norah Jones All A Dream.mp4', 'https://www.youtube.com/watch?v=hnveeZUk6Rg&timestamp=1729777653', 2)
[2024-10-24 09:47:33,166]  INFO {sqlalchemy.engine.Engine:2707} COMMIT
[2024-10-24 09:47:33,168]  INFO {cps.tasks.download:164} Media entry updated in the database.
[2024-10-24 09:47:33,168]  INFO {cps.tasks.download:67} Download task for https://www.youtube.com/watch?v=hnveeZUk6Rg completed successfully.

=IIAB==========================================================================
-rw-r--r-- 1 root root 59978 Oct 24 09:47 /var/log/xklb.log
                        ...ITS LAST 300 LINES FOLLOW...

2024-10-24 09:06:49 - [Debug] Creating fts index: ['path', 'webpath', 'title']
2024-10-24 09:06:49 - [Debug] Processing table: captions
2024-10-24 09:06:49 - [Debug] Creating index: media_id
2024-10-24 09:06:49 - [Debug] Creating index: time
2024-10-24 09:06:49 - [Debug] Creating fts index: ['text']
2024-10-24 09:06:49 - [Debug] Running VACUUM
2024-10-24 09:06:49 - [Debug] Running ANALYZE
2024-10-24 09:06:49 - [Info] 
2024-10-24 09:06:49 - [Info] lb-wrapper's xklb command (tubeadd) completed successfully.
2024-10-24 09:06:49 - [Info] Using yt-dlp 2024.10.22
2024-10-24 09:06:49 - [Info] Running xklb command: lb dl '/library/calibre-web/xklb-metadata.db' --video --search 'https://www.youtube.com/watch?v=6jYtRQ2tHGg' --format best --format-sort 'tbr~1000' --write-thumbnail --subs --live --live-from-start -o '/library/downloads/calibre-web/%(extractor_key,extractor)s/%(uploader,uploader_id)s/%(title).170B_%(view_count)3.2D_[%(id).64B].%(ext)s' -vv
2024-10-24 09:06:50 - [Debug] library v3.0.015 :: /root/.local/share/pipx/venvs/xklb/bin
2024-10-24 09:06:50 - [Debug] ['/usr/local/bin/lb', 'dl', '/library/calibre-web/xklb-metadata.db', '--video', '--search', 'https://www.youtube.com/watch?v=6jYtRQ2tHGg', '--format', 'best', '--format-sort', 'tbr~1000', '--write-thumbnail', '--subs', '--live', '--live-from-start', '-o', '/library/downloads/calibre-web/%(extractor_key,extractor)s/%(uploader,uploader_id)s/%(title).170B_%(view_count)3.2D_[%(id).64B].%(ext)s', '-vv']
2024-10-24 09:06:50 - [Debug] {'include': ['https://www.youtube.com/watch?v=6jYtRQ2tHGg'], 'subs': True, 'live': True, 'paths': []}
2024-10-24 09:06:50 - [Debug] {'time_modified': 0, 'time_deleted': 0, 'download_attempts': 0}
2024-10-24 09:06:50 - [Debug] {'id': 1, 'path': 'https://www.youtube.com/watch?v=6jYtRQ2tHGg', 'title': 'Norah Jones: Tiny Desk Concert', 'duration': 1139, 'time_created': 1729775209, 'size': 0, 'time_modified': 0, 'time_downloaded': 0, 'time_deleted': 0, 'error': None, 'extractor_key': 'Playlist-less media'}
2024-10-24 09:06:50 - [Debug] {'noprogress': True, 'lazy_playlist': True, 'noplaylist': True, 'no_check_certificate': True, 'ignore_no_formats_error': True, 'skip_playlist_after_errors': 21, 'playlistend': 20000, 'extractor_args': {'youtube': {'skip': ['authcheck']}}, 'check_formats': 'selected', 'logger': <xklb.createdb.tube_backend.download.<locals>.DictLogger object at 0xee56f21114f0>, 'postprocessors': [{'key': 'FFmpegMetadata'}, {'key': 'FFmpegEmbedSubtitle'}], 'playlist_items': '1', 'extractor_retries': 3, 'retries': 12, 'retry_sleep_functions': {'extractor': <function download.<locals>.<lambda> at 0xee56f211eb60>, 'http': <function download.<locals>.<lambda> at 0xee56f211ec00>, 'fragment': <function download.<locals>.<lambda> at 0xee56f211eca0>}, 'outtmpl': {'default': '/library/downloads/calibre-web/%(extractor_key,extractor)s/%(uploader,uploader_id)s/%(title).170B_%(view_count)3.2D_[%(id).64B].%(ext)s'}, 'progress_hooks': [<function download.<locals>.<lambda> at 0xee56f211ed40>], 'subtitlesformat': 'srt/best', 'writesubtitles': True, 'writeautomaticsub': True, 'format': 'best', 'format_sort': ['tbr~1000'], 'writethumbnail': True, 'live_from_start': True, '_warnings': ['"-f best" selects the best pre-merged format which is often not the best option.\n         To let yt-dlp download and merge the best available formats, simply do not pass any format selection.\n         If you know what you are doing and want only the best pre-merged format, use "-f b" instead to suppress this warning'], 'include': ['https://www.youtube.com/watch?v=6jYtRQ2tHGg'], 'subs': True, 'live': True}
2024-10-24 09:06:50 - [Debug] [yt-dlp]: Downloading https://www.youtube.com/watch?v=6jYtRQ2tHGg
2024-10-24 09:07:11 - [Debug] [https://www.youtube.com/watch?v=6jYtRQ2tHGg]: Downloaded to /library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4
2024-10-24 09:07:11 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '0.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:07:11 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:07:11 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 0.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:07:11 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '345.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:07:11 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:07:11 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 345.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:07:11 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '115.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:07:11 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:07:11 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 115.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:07:11 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '230.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:07:11 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:07:11 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 230.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:07:11 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '575.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:07:11 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:07:11 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 575.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:07:11 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '460.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:07:11 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:07:11 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 460.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:07:11 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '1035.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:07:11 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:07:11 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 1035.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:07:11 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '920.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:07:11 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:07:11 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 920.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:07:11 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '805.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:07:11 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:07:11 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 805.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:07:11 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '690.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:07:11 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:07:11 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 690.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:07:11 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '1138.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:07:11 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:07:11 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 1138.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:07:25 - [Debug] ('ffprobe', '-show_entries', 'stream=r_frame_rate,nb_read_frames,duration', '-select_streams', 'v', '-count_frames', '-of', 'json', '-threads', '1', '-v', '0', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4')
2024-10-24 09:07:25 - [Debug] {
2024-10-24 09:07:25 - [Debug] "programs": [
2024-10-24 09:07:25 - [Debug] 
2024-10-24 09:07:25 - [Debug] ],
2024-10-24 09:07:25 - [Debug] "streams": [
2024-10-24 09:07:25 - [Debug] {
2024-10-24 09:07:25 - [Debug] "r_frame_rate": "24000/1001",
2024-10-24 09:07:25 - [Debug] "duration": "1139.429958",
2024-10-24 09:07:25 - [Debug] "nb_read_frames": "27319"
2024-10-24 09:07:25 - [Debug] }
2024-10-24 09:07:25 - [Debug] ]
2024-10-24 09:07:25 - [Debug] }
2024-10-24 09:07:25 - [Debug] Extra media data {'time_modified': 0, 'time_downloaded': 0, 'time_deleted': 0, 'requested_subtitles_en_ext': 'vtt', 'requested_subtitles_en_url': 'https://www.youtube.com/api/timedtext?v=6jYtRQ2tHGg&ei=a0YaZ5-dCMaKkucPxeX6mA8&caps=asr&opi=112496729&exp=xbt&xoaf=5&hl=en&ip=0.0.0.0&ipbits=0&expire=1729800411&sparams=ip%2Cipbits%2Cexpire%2Cv%2Cei%2Ccaps%2Copi%2Cexp%2Cxoaf&signature=D2FA0E294D2576A79ED75AAFD6F723DE15EA0CBF.53C82C35413E0EAE0F78D5B53662E133CF6BA37C&key=yt8&kind=asr&lang=en&fmt=vtt', 'requested_subtitles_en_name': 'English', 'requested_subtitles_en_filepath': '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].en.vtt', 'corruption': 0}
2024-10-24 09:07:25 - [Info] lb-wrapper's xklb command (dl) completed successfully.
2024-10-24 09:22:13 - [Info] Using yt-dlp 2024.10.22
2024-10-24 09:22:13 - [Info] Running xklb command: lb tubeadd '/library/calibre-web/xklb-metadata.db' 'https://www.youtube.com/watch?v=6jYtRQ2tHGg' --force -vv
2024-10-24 09:22:13 - [Debug] library v3.0.015 :: /root/.local/share/pipx/venvs/xklb/bin
2024-10-24 09:22:13 - [Debug] ['/usr/local/bin/lb', 'tubeadd', '/library/calibre-web/xklb-metadata.db', 'https://www.youtube.com/watch?v=6jYtRQ2tHGg', '--force', '-vv']
2024-10-24 09:22:13 - [Debug] {'force': True, 'paths': ['https://www.youtube.com/watch?v=6jYtRQ2tHGg']}
2024-10-24 09:22:13 - [Debug] {'noprogress': True, 'skip_download': True, 'lazy_playlist': True, 'extract_flat': True, 'no_check_certificate': True, 'ignore_no_formats_error': True, 'skip_playlist_after_errors': 21, 'playlistend': 20000, 'force': True}
2024-10-24 09:22:13 - [Debug] yt-dlp initialized 0.0557
2024-10-24 09:22:13 - [Info] [youtube] Extracting URL: https://www.youtube.com/watch?v=6jYtRQ2tHGg
2024-10-24 09:22:13 - [Info] [youtube] 6jYtRQ2tHGg: Downloading webpage
2024-10-24 09:22:14 - [Info] [youtube] 6jYtRQ2tHGg: Downloading ios player API JSON
2024-10-24 09:22:14 - [Info] [youtube] 6jYtRQ2tHGg: Downloading mweb player API JSON
2024-10-24 09:22:15 - [Debug] Importing playlist-less media https://www.youtube.com/watch?v=6jYtRQ2tHGg
2024-10-24 09:22:15 - [Debug] media.playlist_media_add 1.6234
2024-10-24 09:22:15 - [Debug] ydl.extract_info done 0.0618
2024-10-24 09:22:15 - [Debug] 
2024-10-24 09:22:15 - [Debug] Optimizing database
2024-10-24 09:22:15 - [Debug] Processing table: playlists
2024-10-24 09:22:15 - [Debug] Creating index: id
2024-10-24 09:22:15 - [Debug] Creating index: time_modified
2024-10-24 09:22:15 - [Debug] Creating index: time_deleted
2024-10-24 09:22:15 - [Debug] Creating index: time_created
2024-10-24 09:22:15 - [Debug] Creating index: hours_update_delay
2024-10-24 09:22:15 - [Debug] Creating index: uploader
2024-10-24 09:22:15 - [Debug] Creating index: extractor_config
2024-10-24 09:22:15 - [Debug] Creating index: extractor_key
2024-10-24 09:22:15 - [Debug] Creating index: path
2024-10-24 09:22:15 - [Debug] Creating index: profile
2024-10-24 09:22:15 - [Debug] Creating fts index: ['path', 'title']
2024-10-24 09:22:15 - [Debug] Processing table: media
2024-10-24 09:22:15 - [Debug] Transforming column order: ['id', 'time_deleted', 'playlists_id', 'size', 'duration', 'time_created', 'time_modified', 'time_downloaded', 'fps', 'view_count', 'time_uploaded', 'width', 'height', 'video_count', 'audio_count', 'chapter_count', 'other_count', 'subtitle_count', 'download_attempts', 'path', 'webpath', 'extractor_id']
2024-10-24 09:22:15 - [Debug] Creating index: id
2024-10-24 09:22:15 - [Debug] Creating index: time_deleted
2024-10-24 09:22:15 - [Debug] Creating index: playlists_id
2024-10-24 09:22:15 - [Debug] Creating index: size
2024-10-24 09:22:15 - [Debug] Creating index: duration
2024-10-24 09:22:15 - [Debug] Creating index: time_created
2024-10-24 09:22:15 - [Debug] Creating index: time_modified
2024-10-24 09:22:15 - [Debug] Creating index: time_downloaded
2024-10-24 09:22:15 - [Debug] Creating index: fps
2024-10-24 09:22:15 - [Debug] Creating index: view_count
2024-10-24 09:22:15 - [Debug] Creating index: time_uploaded
2024-10-24 09:22:15 - [Debug] Creating index: width
2024-10-24 09:22:15 - [Debug] Creating index: height
2024-10-24 09:22:15 - [Debug] Creating index: video_count
2024-10-24 09:22:15 - [Debug] Creating index: audio_count
2024-10-24 09:22:15 - [Debug] Creating index: chapter_count
2024-10-24 09:22:15 - [Debug] Creating index: other_count
2024-10-24 09:22:15 - [Debug] Creating index: subtitle_count
2024-10-24 09:22:15 - [Debug] Creating index: download_attempts
2024-10-24 09:22:15 - [Debug] Creating index: live_status
2024-10-24 09:22:15 - [Debug] Creating index: type
2024-10-24 09:22:15 - [Debug] Creating index: error
2024-10-24 09:22:15 - [Debug] Creating index: audio_codecs
2024-10-24 09:22:15 - [Debug] Creating index: uploader
2024-10-24 09:22:15 - [Debug] Creating index: video_codecs
2024-10-24 09:22:15 - [Debug] Creating index: language
2024-10-24 09:22:15 - [Debug] Creating index: path
2024-10-24 09:22:15 - [Debug] Creating index: subtitle_codecs
2024-10-24 09:22:15 - [Debug] Creating index: other_codecs
2024-10-24 09:22:15 - [Debug] Creating fts index: ['path', 'webpath', 'title']
2024-10-24 09:22:15 - [Debug] Processing table: captions
2024-10-24 09:22:15 - [Debug] Creating index: rowid
2024-10-24 09:22:15 - [Debug] Creating index: media_id
2024-10-24 09:22:15 - [Debug] Creating index: time
2024-10-24 09:22:15 - [Debug] Creating fts index: ['text']
2024-10-24 09:22:15 - [Debug] Running VACUUM
2024-10-24 09:22:15 - [Debug] Running ANALYZE
2024-10-24 09:22:15 - [Info] 
2024-10-24 09:22:15 - [Info] lb-wrapper's xklb command (tubeadd) completed successfully.
2024-10-24 09:22:41 - [Info] Using yt-dlp 2024.10.22
2024-10-24 09:22:41 - [Info] Running xklb command: lb tubeadd '/library/calibre-web/xklb-metadata.db' 'https://www.youtube.com/watch?v=6jYtRQ2tHGg' --force -vv
2024-10-24 09:22:41 - [Debug] library v3.0.015 :: /root/.local/share/pipx/venvs/xklb/bin
2024-10-24 09:22:41 - [Debug] ['/usr/local/bin/lb', 'tubeadd', '/library/calibre-web/xklb-metadata.db', 'https://www.youtube.com/watch?v=6jYtRQ2tHGg', '--force', '-vv']
2024-10-24 09:22:41 - [Debug] {'force': True, 'paths': ['https://www.youtube.com/watch?v=6jYtRQ2tHGg']}
2024-10-24 09:22:41 - [Debug] {'noprogress': True, 'skip_download': True, 'lazy_playlist': True, 'extract_flat': True, 'no_check_certificate': True, 'ignore_no_formats_error': True, 'skip_playlist_after_errors': 21, 'playlistend': 20000, 'force': True}
2024-10-24 09:22:41 - [Debug] yt-dlp initialized 0.0523
2024-10-24 09:22:41 - [Info] [youtube] Extracting URL: https://www.youtube.com/watch?v=6jYtRQ2tHGg
2024-10-24 09:22:41 - [Info] [youtube] 6jYtRQ2tHGg: Downloading webpage
2024-10-24 09:22:42 - [Info] [youtube] 6jYtRQ2tHGg: Downloading ios player API JSON
2024-10-24 09:22:42 - [Info] [youtube] 6jYtRQ2tHGg: Downloading mweb player API JSON
2024-10-24 09:22:43 - [Debug] Importing playlist-less media https://www.youtube.com/watch?v=6jYtRQ2tHGg
2024-10-24 09:22:43 - [Debug] media.playlist_media_add 1.6159
2024-10-24 09:22:43 - [Debug] ydl.extract_info done 0.0351
2024-10-24 09:22:43 - [Info] 
2024-10-24 09:22:43 - [Info] lb-wrapper's xklb command (tubeadd) completed successfully.
2024-10-24 09:22:43 - [Info] Using yt-dlp 2024.10.22
2024-10-24 09:22:43 - [Info] Running xklb command: lb dl '/library/calibre-web/xklb-metadata.db' --video --search 'https://www.youtube.com/watch?v=6jYtRQ2tHGg' --format best --format-sort 'tbr~1000' --write-thumbnail --subs --live --live-from-start -o '/library/downloads/calibre-web/%(extractor_key,extractor)s/%(uploader,uploader_id)s/%(title).170B_%(view_count)3.2D_[%(id).64B].%(ext)s' -vv
2024-10-24 09:22:43 - [Debug] library v3.0.015 :: /root/.local/share/pipx/venvs/xklb/bin
2024-10-24 09:22:43 - [Debug] ['/usr/local/bin/lb', 'dl', '/library/calibre-web/xklb-metadata.db', '--video', '--search', 'https://www.youtube.com/watch?v=6jYtRQ2tHGg', '--format', 'best', '--format-sort', 'tbr~1000', '--write-thumbnail', '--subs', '--live', '--live-from-start', '-o', '/library/downloads/calibre-web/%(extractor_key,extractor)s/%(uploader,uploader_id)s/%(title).170B_%(view_count)3.2D_[%(id).64B].%(ext)s', '-vv']
2024-10-24 09:22:44 - [Debug] {'include': ['https://www.youtube.com/watch?v=6jYtRQ2tHGg'], 'subs': True, 'live': True, 'paths': []}
2024-10-24 09:22:44 - [Debug] {'time_modified': 0, 'time_deleted': 0, 'download_attempts': None}
2024-10-24 09:22:44 - [Debug] {'id': 1, 'playlists_id': None, 'path': 'https://www.youtube.com/watch?v=6jYtRQ2tHGg', 'playlist_path': None, 'title': 'Norah Jones: Tiny Desk Concert', 'duration': 1139, 'time_created': 1729776135, 'size': 0, 'time_modified': 0, 'download_attempts': None, 'time_downloaded': 0, 'time_deleted': 0, 'error': None, 'extractor_config': None, 'extractor_key': None}
2024-10-24 09:22:44 - [Debug] {'noprogress': True, 'lazy_playlist': True, 'noplaylist': True, 'no_check_certificate': True, 'ignore_no_formats_error': True, 'skip_playlist_after_errors': 21, 'playlistend': 20000, 'extractor_args': {'youtube': {'skip': ['authcheck']}}, 'check_formats': 'selected', 'logger': <xklb.createdb.tube_backend.download.<locals>.DictLogger object at 0xecfebea75310>, 'postprocessors': [{'key': 'FFmpegMetadata'}, {'key': 'FFmpegEmbedSubtitle'}], 'playlist_items': '1', 'extractor_retries': 3, 'retries': 12, 'retry_sleep_functions': {'extractor': <function download.<locals>.<lambda> at 0xecfebea82ca0>, 'http': <function download.<locals>.<lambda> at 0xecfebea82d40>, 'fragment': <function download.<locals>.<lambda> at 0xecfebea82de0>}, 'outtmpl': {'default': '/library/downloads/calibre-web/%(extractor_key,extractor)s/%(uploader,uploader_id)s/%(title).170B_%(view_count)3.2D_[%(id).64B].%(ext)s'}, 'progress_hooks': [<function download.<locals>.<lambda> at 0xecfebea82e80>], 'subtitlesformat': 'srt/best', 'writesubtitles': True, 'writeautomaticsub': True, 'format': 'best', 'format_sort': ['tbr~1000'], 'writethumbnail': True, 'live_from_start': True, '_warnings': ['"-f best" selects the best pre-merged format which is often not the best option.\n         To let yt-dlp download and merge the best available formats, simply do not pass any format selection.\n         If you know what you are doing and want only the best pre-merged format, use "-f b" instead to suppress this warning'], 'include': ['https://www.youtube.com/watch?v=6jYtRQ2tHGg'], 'subs': True, 'live': True}
2024-10-24 09:22:44 - [Debug] [yt-dlp]: Downloading https://www.youtube.com/watch?v=6jYtRQ2tHGg
2024-10-24 09:23:01 - [Debug] [https://www.youtube.com/watch?v=6jYtRQ2tHGg]: Downloaded to /library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4
2024-10-24 09:23:01 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '0.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:23:01 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:23:01 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 0.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:23:01 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '230.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:23:01 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:23:01 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 230.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:23:01 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '115.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:23:01 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:23:01 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 115.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:23:01 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '460.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:23:01 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:23:01 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 460.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:23:01 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '345.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:23:01 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:23:01 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 345.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:23:01 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '690.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:23:01 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:23:01 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 690.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:23:01 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '805.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:23:01 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:23:01 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 805.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:23:01 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '575.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:23:01 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:23:01 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 575.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:23:01 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '1035.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:23:01 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:23:01 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 1035.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:23:01 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '920.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:23:01 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:23:01 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 920.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:23:01 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '1138.00', '-i', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:23:01 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:23:01 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 1138.00 -i '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:23:14 - [Debug] ('ffprobe', '-show_entries', 'stream=r_frame_rate,nb_read_frames,duration', '-select_streams', 'v', '-count_frames', '-of', 'json', '-threads', '1', '-v', '0', '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4')
2024-10-24 09:23:14 - [Debug] {
2024-10-24 09:23:14 - [Debug] "programs": [
2024-10-24 09:23:14 - [Debug] 
2024-10-24 09:23:14 - [Debug] ],
2024-10-24 09:23:14 - [Debug] "streams": [
2024-10-24 09:23:14 - [Debug] {
2024-10-24 09:23:14 - [Debug] "r_frame_rate": "24000/1001",
2024-10-24 09:23:14 - [Debug] "duration": "1139.429958",
2024-10-24 09:23:14 - [Debug] "nb_read_frames": "27319"
2024-10-24 09:23:14 - [Debug] }
2024-10-24 09:23:14 - [Debug] ]
2024-10-24 09:23:14 - [Debug] }
2024-10-24 09:23:14 - [Debug] Extra media data {'time_modified': 0, 'time_downloaded': 0, 'time_deleted': 0, 'requested_subtitles_en_ext': 'vtt', 'requested_subtitles_en_url': 'https://www.youtube.com/api/timedtext?v=6jYtRQ2tHGg&ei=JEoaZ6j2OLSIkucP5srx6Ak&caps=asr&opi=112496729&exp=xbt&xoaf=5&hl=en&ip=0.0.0.0&ipbits=0&expire=1729801364&sparams=ip%2Cipbits%2Cexpire%2Cv%2Cei%2Ccaps%2Copi%2Cexp%2Cxoaf&signature=0D360315CC892D1CC447B846B8DB94EDB0F1F2F7.D6502A050B5DC21A6857D00FC5F9E8D359963279&key=yt8&kind=asr&lang=en&fmt=vtt', 'requested_subtitles_en_name': 'English', 'requested_subtitles_en_filepath': '/library/downloads/calibre-web/Youtube/NPR Music/Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].en.vtt', 'corruption': 0}
2024-10-24 09:23:15 - [Info] lb-wrapper's xklb command (dl) completed successfully.
2024-10-24 09:43:58 - [Info] Using yt-dlp 2024.10.22
2024-10-24 09:43:58 - [Info] Running xklb command: lb tubeadd '/library/calibre-web/xklb-metadata.db' 'https://www.youtube.com/watch?v=hnveeZUk6Rg' --force -vv
2024-10-24 09:43:59 - [Debug] library v3.0.015 :: /root/.local/share/pipx/venvs/xklb/bin
2024-10-24 09:43:59 - [Debug] ['/usr/local/bin/lb', 'tubeadd', '/library/calibre-web/xklb-metadata.db', 'https://www.youtube.com/watch?v=hnveeZUk6Rg', '--force', '-vv']
2024-10-24 09:43:59 - [Debug] {'force': True, 'paths': ['https://www.youtube.com/watch?v=hnveeZUk6Rg']}
2024-10-24 09:43:59 - [Debug] {'noprogress': True, 'skip_download': True, 'lazy_playlist': True, 'extract_flat': True, 'no_check_certificate': True, 'ignore_no_formats_error': True, 'skip_playlist_after_errors': 21, 'playlistend': 20000, 'force': True}
2024-10-24 09:43:59 - [Debug] yt-dlp initialized 0.0572
2024-10-24 09:43:59 - [Info] [youtube] Extracting URL: https://www.youtube.com/watch?v=hnveeZUk6Rg
2024-10-24 09:43:59 - [Info] [youtube] hnveeZUk6Rg: Downloading webpage
2024-10-24 09:44:00 - [Info] [youtube] hnveeZUk6Rg: Downloading ios player API JSON
2024-10-24 09:44:00 - [Info] [youtube] hnveeZUk6Rg: Downloading mweb player API JSON
2024-10-24 09:44:00 - [Debug] Importing playlist-less media https://www.youtube.com/watch?v=hnveeZUk6Rg
2024-10-24 09:44:00 - [Debug] media.playlist_media_add 1.6976
2024-10-24 09:44:01 - [Debug] ydl.extract_info done 0.0686
2024-10-24 09:44:01 - [Info] 
2024-10-24 09:44:01 - [Info] lb-wrapper's xklb command (tubeadd) completed successfully.
2024-10-24 09:46:44 - [Info] Using yt-dlp 2024.10.22
2024-10-24 09:46:44 - [Info] Running xklb command: lb tubeadd '/library/calibre-web/xklb-metadata.db' 'https://www.youtube.com/watch?v=hnveeZUk6Rg' --force -vv
2024-10-24 09:46:44 - [Debug] library v3.0.015 :: /root/.local/share/pipx/venvs/xklb/bin
2024-10-24 09:46:44 - [Debug] ['/usr/local/bin/lb', 'tubeadd', '/library/calibre-web/xklb-metadata.db', 'https://www.youtube.com/watch?v=hnveeZUk6Rg', '--force', '-vv']
2024-10-24 09:46:44 - [Debug] {'force': True, 'paths': ['https://www.youtube.com/watch?v=hnveeZUk6Rg']}
2024-10-24 09:46:45 - [Debug] {'noprogress': True, 'skip_download': True, 'lazy_playlist': True, 'extract_flat': True, 'no_check_certificate': True, 'ignore_no_formats_error': True, 'skip_playlist_after_errors': 21, 'playlistend': 20000, 'force': True}
2024-10-24 09:46:45 - [Debug] yt-dlp initialized 0.0672
2024-10-24 09:46:45 - [Info] [youtube] Extracting URL: https://www.youtube.com/watch?v=hnveeZUk6Rg
2024-10-24 09:46:45 - [Info] [youtube] hnveeZUk6Rg: Downloading webpage
2024-10-24 09:46:45 - [Info] [youtube] hnveeZUk6Rg: Downloading ios player API JSON
2024-10-24 09:46:45 - [Info] [youtube] hnveeZUk6Rg: Downloading mweb player API JSON
2024-10-24 09:46:46 - [Debug] Importing playlist-less media https://www.youtube.com/watch?v=hnveeZUk6Rg
2024-10-24 09:46:46 - [Debug] media.playlist_media_add 1.5598
2024-10-24 09:46:46 - [Debug] ydl.extract_info done 0.0462
2024-10-24 09:46:46 - [Info] 
2024-10-24 09:46:46 - [Info] lb-wrapper's xklb command (tubeadd) completed successfully.
2024-10-24 09:46:46 - [Info] Using yt-dlp 2024.10.22
2024-10-24 09:46:46 - [Info] Running xklb command: lb dl '/library/calibre-web/xklb-metadata.db' --video --search 'https://www.youtube.com/watch?v=hnveeZUk6Rg' --format best --format-sort 'tbr~1000' --write-thumbnail --subs --live --live-from-start -o '/library/downloads/calibre-web/%(extractor_key,extractor)s/%(uploader,uploader_id)s/%(title).170B_%(view_count)3.2D_[%(id).64B].%(ext)s' -vv
2024-10-24 09:46:47 - [Debug] library v3.0.015 :: /root/.local/share/pipx/venvs/xklb/bin
2024-10-24 09:46:47 - [Debug] ['/usr/local/bin/lb', 'dl', '/library/calibre-web/xklb-metadata.db', '--video', '--search', 'https://www.youtube.com/watch?v=hnveeZUk6Rg', '--format', 'best', '--format-sort', 'tbr~1000', '--write-thumbnail', '--subs', '--live', '--live-from-start', '-o', '/library/downloads/calibre-web/%(extractor_key,extractor)s/%(uploader,uploader_id)s/%(title).170B_%(view_count)3.2D_[%(id).64B].%(ext)s', '-vv']
2024-10-24 09:46:47 - [Debug] {'include': ['https://www.youtube.com/watch?v=hnveeZUk6Rg'], 'subs': True, 'live': True, 'paths': []}
2024-10-24 09:46:47 - [Debug] {'time_modified': 0, 'time_deleted': 0, 'download_attempts': None}
2024-10-24 09:46:47 - [Debug] {'id': 2, 'playlists_id': None, 'path': 'https://www.youtube.com/watch?v=hnveeZUk6Rg', 'playlist_path': None, 'title': 'Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)', 'duration': 1642, 'time_created': 1729777440, 'size': 0, 'time_modified': 0, 'download_attempts': None, 'time_downloaded': 0, 'time_deleted': 0, 'error': None, 'extractor_config': None, 'extractor_key': None}
2024-10-24 09:46:47 - [Debug] {'noprogress': True, 'lazy_playlist': True, 'noplaylist': True, 'no_check_certificate': True, 'ignore_no_formats_error': True, 'skip_playlist_after_errors': 21, 'playlistend': 20000, 'extractor_args': {'youtube': {'skip': ['authcheck']}}, 'check_formats': 'selected', 'logger': <xklb.createdb.tube_backend.download.<locals>.DictLogger object at 0xeee88a415dc0>, 'postprocessors': [{'key': 'FFmpegMetadata'}, {'key': 'FFmpegEmbedSubtitle'}], 'playlist_items': '1', 'extractor_retries': 3, 'retries': 12, 'retry_sleep_functions': {'extractor': <function download.<locals>.<lambda> at 0xeee88a422ca0>, 'http': <function download.<locals>.<lambda> at 0xeee88a422d40>, 'fragment': <function download.<locals>.<lambda> at 0xeee88a422de0>}, 'outtmpl': {'default': '/library/downloads/calibre-web/%(extractor_key,extractor)s/%(uploader,uploader_id)s/%(title).170B_%(view_count)3.2D_[%(id).64B].%(ext)s'}, 'progress_hooks': [<function download.<locals>.<lambda> at 0xeee88a422e80>], 'subtitlesformat': 'srt/best', 'writesubtitles': True, 'writeautomaticsub': True, 'format': 'best', 'format_sort': ['tbr~1000'], 'writethumbnail': True, 'live_from_start': True, '_warnings': ['"-f best" selects the best pre-merged format which is often not the best option.\n         To let yt-dlp download and merge the best available formats, simply do not pass any format selection.\n         If you know what you are doing and want only the best pre-merged format, use "-f b" instead to suppress this warning'], 'include': ['https://www.youtube.com/watch?v=hnveeZUk6Rg'], 'subs': True, 'live': True}
2024-10-24 09:46:47 - [Debug] [yt-dlp]: Downloading https://www.youtube.com/watch?v=hnveeZUk6Rg
2024-10-24 09:47:19 - [Debug] [https://www.youtube.com/watch?v=hnveeZUk6Rg]: Downloaded to /library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4
2024-10-24 09:47:19 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '166.00', '-i', '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:47:19 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:47:19 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 166.00 -i '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:47:19 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '0.00', '-i', '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:47:19 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:47:19 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 0.00 -i '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:47:19 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '332.00', '-i', '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:47:19 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:47:19 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 332.00 -i '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:47:19 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '996.00', '-i', '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:47:19 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:47:19 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 996.00 -i '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:47:19 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '830.00', '-i', '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:47:19 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:47:19 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 830.00 -i '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:47:19 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '664.00', '-i', '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:47:19 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:47:19 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 664.00 -i '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:47:19 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '498.00', '-i', '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:47:19 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:47:19 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 498.00 -i '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:47:19 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '1640.00', '-i', '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:47:19 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:47:19 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 1640.00 -i '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:47:19 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '1162.00', '-i', '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:47:19 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:47:19 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 1162.00 -i '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:47:19 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '1494.00', '-i', '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:47:19 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:47:19 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 1494.00 -i '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:47:19 - [Debug] ('systemd-run', '--user', '-p', 'MemoryMax=4G', '-p', 'MemorySwapMax=1G', '--pty', '--pipe', '--same-dir', '--wait', '--collect', '--service-type=exec', '--quiet', '--', 'ffmpeg', '-nostdin', '-hide_banner', '-nostats', '-xerror', '-v', '16', '-err_detect', 'explode', '-ss', '1328.00', '-i', '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4', '-t', '1', '-f', 'null', '/dev/null')
2024-10-24 09:47:19 - [Debug] Failed to connect to bus: No medium found
2024-10-24 09:47:19 - [Debug] [systemd-run --user -p MemoryMax=4G -p MemorySwapMax=1G --pty --pipe --same-dir --wait --collect --service-type=exec --quiet -- ffmpeg -nostdin -hide_banner -nostats -xerror -v 16 -err_detect explode -ss 1328.00 -i '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4' -t 1 -f null /dev/null] exited 1
2024-10-24 09:47:32 - [Debug] ('ffprobe', '-show_entries', 'stream=r_frame_rate,nb_read_frames,duration', '-select_streams', 'v', '-count_frames', '-of', 'json', '-threads', '1', '-v', '0', '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4')
2024-10-24 09:47:32 - [Debug] {
2024-10-24 09:47:32 - [Debug] "programs": [
2024-10-24 09:47:32 - [Debug] 
2024-10-24 09:47:32 - [Debug] ],
2024-10-24 09:47:32 - [Debug] "streams": [
2024-10-24 09:47:32 - [Debug] {
2024-10-24 09:47:32 - [Debug] "r_frame_rate": "30/1",
2024-10-24 09:47:32 - [Debug] "duration": "1641.600000",
2024-10-24 09:47:32 - [Debug] "nb_read_frames": "49248"
2024-10-24 09:47:32 - [Debug] }
2024-10-24 09:47:32 - [Debug] ]
2024-10-24 09:47:32 - [Debug] }
2024-10-24 09:47:32 - [Debug] Extra media data {'time_modified': 0, 'time_downloaded': 0, 'time_deleted': 0, 'requested_subtitles_en_ext': 'vtt', 'requested_subtitles_en_url': 'https://www.youtube.com/api/timedtext?v=hnveeZUk6Rg&ei=yE8aZ7SwC7e1kucPkoGB0Qw&caps=asr&opi=112496729&exp=xbt&xoaf=5&hl=en&ip=0.0.0.0&ipbits=0&expire=1729802808&sparams=ip%2Cipbits%2Cexpire%2Cv%2Cei%2Ccaps%2Copi%2Cexp%2Cxoaf&signature=B68C890693BE9EFC2360ACB83DB848A0BA530ADF.314033DCDDC73151D1D3859440FB95396220ACAF&key=yt8&kind=asr&lang=en&fmt=vtt', 'requested_subtitles_en_name': 'English', 'requested_subtitles_en_filepath': '/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].en.vtt', 'corruption': 0}
2024-10-24 09:47:33 - [Info] lb-wrapper's xklb command (dl) completed successfully.

=IIAB==========================================================================
COMMAND: /usr/bin/journalctl -t IIAB-CMDSRV    # Admin Console CMDSRV log

-- No entries --




5. FIREWALL RULES

=IIAB==========================================================================
COMMAND: /usr/bin/sudo iptables-save    # Firewall rules

# Generated by iptables-save v1.8.10 (nf_tables) on Thu Oct 24 09:52:53 2024
*filter
:INPUT ACCEPT [0:0]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [0:0]
COMMIT
# Completed on Thu Oct 24 09:52:53 2024
# Generated by iptables-save v1.8.10 (nf_tables) on Thu Oct 24 09:52:53 2024
*nat
:PREROUTING ACCEPT [0:0]
:INPUT ACCEPT [0:0]
:OUTPUT ACCEPT [0:0]
:POSTROUTING ACCEPT [0:0]
COMMIT
# Completed on Thu Oct 24 09:52:53 2024

=IIAB==========================================================================
COMMAND: /usr/bin/sudo ufw status verbose    # Firewall status & rules

Status: inactive




6. LOG FILES (e.g. LAST 100 LINES OF EACH)

=IIAB==========================================================================
COMMAND: /usr/bin/grep -B2 "SEE ERROR ABOVE" /opt/iiab/iiab/*.log    # for skip_role_on_error


=IIAB==========================================================================
-rw-r--r-- 1 root root 218858 Oct 24 08:55 /opt/iiab/iiab/iiab-install.log
                        ...ITS LAST 100 LINES FOLLOW...

2024-10-24 08:55:52,564 p=2724 u=root n=ansible | TASK [network : Setting wireless LAN as only interface - RPi] ******************
2024-10-24 08:55:52,572 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:52,578 p=2724 u=root n=ansible | TASK [network : In VM disable LAN - needs local_vars entry to activate] ********
2024-10-24 08:55:52,587 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:52,593 p=2724 u=root n=ansible | TASK [network : Has old gateway and no discovered gateway setting WAN] *********
2024-10-24 08:55:52,600 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:52,606 p=2724 u=root n=ansible | TASK [network : Add 'detected_network' variable values to /etc/iiab/iiab.ini] ***
2024-10-24 08:55:52,716 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'has_ifcfg_gw', 'value': 'none'})
2024-10-24 08:55:52,812 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'prior_gateway_device', 'value': 'unset'})
2024-10-24 08:55:52,908 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'dhcpcd_result', 'value': 'not-found'})
2024-10-24 08:55:53,006 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'network_manager_active', 'value': False})
2024-10-24 08:55:53,105 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'systemd_networkd_active', 'value': True})
2024-10-24 08:55:53,203 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'wan_in_interfaces', 'value': False})
2024-10-24 08:55:53,299 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'wireless_list_1(wifi1)', 'value': 'not found-1'})
2024-10-24 08:55:53,395 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'wireless_list_2(wifi2)', 'value': 'not found-2'})
2024-10-24 08:55:53,493 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'num_wifi_interfaces', 'value': '0'})
2024-10-24 08:55:53,589 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'discovered_wireless_iface', 'value': 'none'})
2024-10-24 08:55:53,686 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'discovered_wired_iface', 'value': 'tailscale0'})
2024-10-24 08:55:53,783 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'exclude_devices', 'value': 'enp0s2'})
2024-10-24 08:55:53,880 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'num_lan_interfaces', 'value': '1'})
2024-10-24 08:55:53,976 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'gui_static_wan', 'value': False})
2024-10-24 08:55:54,073 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'iiab_lan_iface', 'value': 'br0'})
2024-10-24 08:55:54,170 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'iiab_wan_iface', 'value': 'enp0s1'})
2024-10-24 08:55:54,268 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'can_be_ap', 'value': False})
2024-10-24 08:55:54,276 p=2724 u=root n=ansible | TASK [network : I'm not guessing declare gateway please] ***********************
2024-10-24 08:55:54,284 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,290 p=2724 u=root n=ansible | TASK [network : Set 'no_net_restart: True' if has_wifi_gateway is defined] *****
2024-10-24 08:55:54,298 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,304 p=2724 u=root n=ansible | TASK [network : computed_network] **********************************************
2024-10-24 08:55:54,322 p=2724 u=root n=ansible | included: /opt/iiab/iiab/roles/network/tasks/computed_network.yml for 127.0.0.1
2024-10-24 08:55:54,334 p=2724 u=root n=ansible | TASK [network : gui-static-wan] ************************************************
2024-10-24 08:55:54,341 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,347 p=2724 u=root n=ansible | TASK [network : Undo gui-static-wan by requesting new template file] ***********
2024-10-24 08:55:54,354 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,378 p=2724 u=root n=ansible | TASK [network : Using GUI_STATIC info] *****************************************
2024-10-24 08:55:54,385 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,391 p=2724 u=root n=ansible | TASK [network : Checking iiab_wan_enabled] *************************************
2024-10-24 08:55:54,397 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,403 p=2724 u=root n=ansible | TASK [network : Setting GUI wants 'LanController'] *****************************
2024-10-24 08:55:54,413 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,419 p=2724 u=root n=ansible | TASK [network : Setting user_lan_iface for 'LanController' for single interface] ***
2024-10-24 08:55:54,429 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,434 p=2724 u=root n=ansible | TASK [network : Setting user WAN fact] *****************************************
2024-10-24 08:55:54,441 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,447 p=2724 u=root n=ansible | TASK [network : Checking iiab_lan_enabled] *************************************
2024-10-24 08:55:54,453 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,459 p=2724 u=root n=ansible | TASK [network : Setting GUI wants 'Appliance'] *********************************
2024-10-24 08:55:54,469 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,474 p=2724 u=root n=ansible | TASK [network : Setting GUI wants and has active 'Gateway'] ********************
2024-10-24 08:55:54,483 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,489 p=2724 u=root n=ansible | TASK [network : Use old gateway device info if not detected and using static ip] ***
2024-10-24 08:55:54,495 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,502 p=2724 u=root n=ansible | TASK [network : No LAN configured - 'Appliance' mode] **************************
2024-10-24 08:55:54,508 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,514 p=2724 u=root n=ansible | TASK [network : LAN configured - 'LanController' mode] *************************
2024-10-24 08:55:54,521 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,526 p=2724 u=root n=ansible | TASK [network : LAN configured - 'Gateway' mode] *******************************
2024-10-24 08:55:54,535 p=2724 u=root n=ansible | ok: [127.0.0.1]
2024-10-24 08:55:54,542 p=2724 u=root n=ansible | TASK [network : Setting user LAN fact] *****************************************
2024-10-24 08:55:54,548 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:54,555 p=2724 u=root n=ansible | TASK [network : Record IIAB_WAN_DEVICE=enp0s1 to /etc/iiab/iiab.env] ***********
2024-10-24 08:55:54,657 p=2724 u=root n=ansible | changed: [127.0.0.1]
2024-10-24 08:55:54,664 p=2724 u=root n=ansible | TASK [network : Record IIAB_LAN_DEVICE=br0 to /etc/iiab/iiab.env] **************
2024-10-24 08:55:54,766 p=2724 u=root n=ansible | changed: [127.0.0.1]
2024-10-24 08:55:54,773 p=2724 u=root n=ansible | TASK [network : Record 'IIAB_GATEWAY_ENABLED=False' in /etc/iiab/iiab.env] *****
2024-10-24 08:55:54,876 p=2724 u=root n=ansible | ok: [127.0.0.1]
2024-10-24 08:55:54,882 p=2724 u=root n=ansible | TASK [network : Add 'computed_network' variable values to /etc/iiab/iiab.ini] ***
2024-10-24 08:55:54,991 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'iiab_wan_enabled', 'value': True})
2024-10-24 08:55:55,087 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'user_wan_iface', 'value': 'auto'})
2024-10-24 08:55:55,184 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'iiab_wan_iface', 'value': 'enp0s1'})
2024-10-24 08:55:55,281 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'iiab_lan_enabled', 'value': True})
2024-10-24 08:55:55,379 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'user_lan_iface', 'value': 'auto'})
2024-10-24 08:55:55,476 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'iiab_lan_iface', 'value': 'br0'})
2024-10-24 08:55:55,572 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'iiab_network_mode', 'value': 'Gateway'})
2024-10-24 08:55:55,670 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item={'option': 'network_enabled', 'value': False})
2024-10-24 08:55:55,678 p=2724 u=root n=ansible | TASK [network : Install /usr/bin/iiab-hotspot-on|off from template (root:root by default)] ***
2024-10-24 08:55:55,883 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item=hostapd/iiab-hotspot-on)
2024-10-24 08:55:56,076 p=2724 u=root n=ansible | changed: [127.0.0.1] => (item=hostapd/iiab-hotspot-off)
2024-10-24 08:55:56,083 p=2724 u=root n=ansible | TASK [network : Install network packages (including many WiFi tools, and also iptables-persistent for firewall)] ***
2024-10-24 08:55:56,092 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:56,098 p=2724 u=root n=ansible | TASK [network : computed_services] *********************************************
2024-10-24 08:55:56,107 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:56,113 p=2724 u=root n=ansible | TASK [network : enable_services] ***********************************************
2024-10-24 08:55:56,122 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:56,128 p=2724 u=root n=ansible | TASK [network : NetworkManager in use] *****************************************
2024-10-24 08:55:56,137 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:56,143 p=2724 u=root n=ansible | TASK [network : systemd-networkd in use] ***************************************
2024-10-24 08:55:56,151 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:56,158 p=2724 u=root n=ansible | TASK [network : Raspbian can use dhcpcd only with no N-M or SYS-NETD active] ***
2024-10-24 08:55:56,166 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:56,172 p=2724 u=root n=ansible | TASK [network : Not RPi, Not NetworkManager, Not systemd-networkd in use] ******
2024-10-24 08:55:56,181 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:56,187 p=2724 u=root n=ansible | TASK [network : hostapd] *******************************************************
2024-10-24 08:55:56,196 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:56,202 p=2724 u=root n=ansible | TASK [network : Restart services] **********************************************
2024-10-24 08:55:56,211 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:56,217 p=2724 u=root n=ansible | TASK [network : Create /etc/iiab/install-flags/iiab-network-complete on second pass of network role.] ***
2024-10-24 08:55:56,225 p=2724 u=root n=ansible | skipping: [127.0.0.1]
2024-10-24 08:55:56,248 p=2724 u=root n=ansible | PLAY RECAP *********************************************************************
2024-10-24 08:55:56,248 p=2724 u=root n=ansible | 127.0.0.1                  : ok=305  changed=167  unreachable=0    failed=0    skipped=125  rescued=0    ignored=3   

=IIAB==========================================================================
FILE DOES NOT EXIST: /opt/iiab/iiab/iiab-configure.log
=IIAB==========================================================================
FILE DOES NOT EXIST: /opt/iiab/iiab/iiab-debug.log
=IIAB==========================================================================
FILE DOES NOT EXIST: /opt/iiab/iiab/iiab-network.log
=IIAB==========================================================================
FILE DOES NOT EXIST: /opt/iiab/iiab-admin-console/admin-install.log
=IIAB==========================================================================
FILE DOES NOT EXIST: /var/log/messages
=IIAB==========================================================================
-rw-r----- 1 syslog adm 627118 Oct 24 09:50 /var/log/syslog
                        ...ITS LAST 100 LINES FOLLOW...

2024-10-24T13:21:54.151308+00:00 box-20241024 python3[27674]: FROM captions
2024-10-24T13:21:54.151325+00:00 box-20241024 python3[27674]: WHERE captions.text LIKE ?
2024-10-24T13:21:54.151378+00:00 box-20241024 python3[27674]: 2024-10-24 09:21:54,149 INFO sqlalchemy.engine.Engine [cached since 38.47s ago] ('%performance%',)
2024-10-24T13:22:15.859414+00:00 box-20241024 python3[27674]: 2024-10-24 09:22:15,858 INFO sqlalchemy.engine.Engine ROLLBACK
2024-10-24T13:22:43.628999+00:00 box-20241024 python3[27674]: 2024-10-24 09:22:43,628 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2024-10-24T13:22:43.630113+00:00 box-20241024 python3[27674]: 2024-10-24 09:22:43,630 INFO sqlalchemy.engine.Engine SELECT media.path AS media_path, media.duration AS media_duration, media.live_status AS media_live_status
2024-10-24T13:22:43.630152+00:00 box-20241024 python3[27674]: FROM media
2024-10-24T13:22:43.630174+00:00 box-20241024 python3[27674]: WHERE media.path LIKE ? AND (media.error IS NULL OR media.error = ?)
2024-10-24T13:22:43.630197+00:00 box-20241024 python3[27674]: 2024-10-24 09:22:43,630 INFO sqlalchemy.engine.Engine [generated in 0.00013s] ('http%', '')
2024-10-24T13:22:43.633559+00:00 box-20241024 python3[27674]: 2024-10-24 09:22:43,633 INFO sqlalchemy.engine.Engine SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error
2024-10-24T13:22:43.635251+00:00 box-20241024 python3[27674]: FROM media
2024-10-24T13:22:43.635261+00:00 box-20241024 python3[27674]: WHERE ? LIKE (? || media.extractor_id || ?)
2024-10-24T13:22:43.635284+00:00 box-20241024 python3[27674]:  LIMIT ? OFFSET ?
2024-10-24T13:22:43.635313+00:00 box-20241024 python3[27674]: 2024-10-24 09:22:43,633 INFO sqlalchemy.engine.Engine [generated in 0.00014s] ('https://www.youtube.com/watch?v=6jYtRQ2tHGg', '%', '%', 1, 0)
2024-10-24T13:22:43.635626+00:00 box-20241024 python3[27674]: 2024-10-24 09:22:43,634 INFO sqlalchemy.engine.Engine COMMIT
2024-10-24T13:23:15.077326+00:00 box-20241024 python3[27674]: 2024-10-24 09:23:15,076 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2024-10-24T13:23:15.079315+00:00 box-20241024 python3[27674]: 2024-10-24 09:23:15,079 INFO sqlalchemy.engine.Engine SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error
2024-10-24T13:23:15.079860+00:00 box-20241024 python3[27674]: FROM media
2024-10-24T13:23:15.079922+00:00 box-20241024 python3[27674]: WHERE media.webpath = ? AND media.path NOT LIKE ?
2024-10-24T13:23:15.079977+00:00 box-20241024 python3[27674]:  LIMIT ? OFFSET ?
2024-10-24T13:23:15.080020+00:00 box-20241024 python3[27674]: 2024-10-24 09:23:15,079 INFO sqlalchemy.engine.Engine [generated in 0.00033s] ('https://www.youtube.com/watch?v=6jYtRQ2tHGg', 'http%', 1, 0)
2024-10-24T13:23:15.204135+00:00 box-20241024 python3[27674]: 2024-10-24 09:23:15,203 INFO sqlalchemy.engine.Engine SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error
2024-10-24T13:23:15.204370+00:00 box-20241024 python3[27674]: FROM media
2024-10-24T13:23:15.204415+00:00 box-20241024 python3[27674]: WHERE media.extractor_id = ? AND media.path LIKE ?
2024-10-24T13:23:15.204456+00:00 box-20241024 python3[27674]:  LIMIT ? OFFSET ?
2024-10-24T13:23:15.204490+00:00 box-20241024 python3[27674]: 2024-10-24 09:23:15,204 INFO sqlalchemy.engine.Engine [generated in 0.00013s] ('6jYtRQ2tHGg', '%Norah JonesM-oM-<M-^Z Tiny Desk Concert_1.64M_[6jYtRQ2tHGg]%', 1, 0)
2024-10-24T13:23:15.205414+00:00 box-20241024 python3[27674]: 2024-10-24 09:23:15,205 INFO sqlalchemy.engine.Engine SELECT captions.rowid AS captions_rowid, captions.media_id AS captions_media_id, captions.time AS captions_time, captions.text AS captions_text
2024-10-24T13:23:15.205464+00:00 box-20241024 python3[27674]: FROM captions
2024-10-24T13:23:15.205504+00:00 box-20241024 python3[27674]: WHERE captions.media_id = ?
2024-10-24T13:23:15.205573+00:00 box-20241024 python3[27674]:  LIMIT ? OFFSET ?
2024-10-24T13:23:15.205591+00:00 box-20241024 python3[27674]: 2024-10-24 09:23:15,205 INFO sqlalchemy.engine.Engine [generated in 0.00011s] (1, 1, 0)
2024-10-24T13:23:15.322093+00:00 box-20241024 python3[27674]: 2024-10-24 09:23:15,322 INFO sqlalchemy.engine.Engine UPDATE media SET path=?, webpath=? WHERE media.id = ?
2024-10-24T13:23:15.322158+00:00 box-20241024 python3[27674]: 2024-10-24 09:23:15,322 INFO sqlalchemy.engine.Engine [generated in 0.00012s] ('/library/calibre-web/NPR Music/Norah Jones_ Tiny Desk Concert (2)/Norah Jones_ Tiny Desk Concert - NPR Music.mp4', 'https://www.youtube.com/watch?v=6jYtRQ2tHGg&timestamp=1729776195', 1)
2024-10-24T13:23:15.322604+00:00 box-20241024 python3[27674]: 2024-10-24 09:23:15,322 INFO sqlalchemy.engine.Engine COMMIT
2024-10-24T13:23:53.503072+00:00 box-20241024 python3[27674]: 2024-10-24 09:23:53,489 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2024-10-24T13:23:53.504358+00:00 box-20241024 python3[27674]: 2024-10-24 09:23:53,490 INFO sqlalchemy.engine.Engine SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time AS captions_time
2024-10-24T13:23:53.505504+00:00 box-20241024 python3[27674]: FROM captions
2024-10-24T13:23:53.505605+00:00 box-20241024 python3[27674]: WHERE captions.text LIKE ?
2024-10-24T13:23:53.505648+00:00 box-20241024 python3[27674]: 2024-10-24 09:23:53,490 INFO sqlalchemy.engine.Engine [cached since 157.8s ago] ('%performance%',)
2024-10-24T13:24:07.103319+00:00 box-20241024 python3[27674]: 2024-10-24 09:24:07,097 INFO sqlalchemy.engine.Engine SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time AS captions_time
2024-10-24T13:24:07.119075+00:00 box-20241024 python3[27674]: FROM captions
2024-10-24T13:24:07.119175+00:00 box-20241024 python3[27674]: WHERE captions.text LIKE ?
2024-10-24T13:24:07.119247+00:00 box-20241024 python3[27674]: 2024-10-24 09:24:07,099 INFO sqlalchemy.engine.Engine [cached since 171.4s ago] ('%sacrifice%',)
2024-10-24T13:25:01.873002+00:00 box-20241024 CRON[28237]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
2024-10-24T13:30:04.705137+00:00 box-20241024 systemd[1]: Starting sysstat-collect.service - system activity accounting tool...
2024-10-24T13:30:04.746377+00:00 box-20241024 systemd[1]: sysstat-collect.service: Deactivated successfully.
2024-10-24T13:30:04.746731+00:00 box-20241024 systemd[1]: Finished sysstat-collect.service - system activity accounting tool.
2024-10-24T13:35:01.306139+00:00 box-20241024 CRON[28246]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
2024-10-24T13:37:04.672284+00:00 box-20241024 systemd[1]: Starting fwupd-refresh.service - Refresh fwupd metadata and update motd...
2024-10-24T13:37:04.777503+00:00 box-20241024 dbus-daemon[771]: [system] Activating via systemd: service name='org.freedesktop.fwupd' unit='fwupd.service' requested by ':1.63' (uid=990 pid=28249 comm="/usr/bin/fwupdmgr refresh" label="unconfined")
2024-10-24T13:37:04.793218+00:00 box-20241024 systemd[1]: Starting fwupd.service - Firmware update daemon...
2024-10-24T13:37:05.346656+00:00 box-20241024 fwupd[28254]: 13:37:05.346 FuMain               Daemon ready for requests (locale C.UTF-8)
2024-10-24T13:37:05.347270+00:00 box-20241024 dbus-daemon[771]: [system] Successfully activated service 'org.freedesktop.fwupd'
2024-10-24T13:37:05.347424+00:00 box-20241024 systemd[1]: Started fwupd.service - Firmware update daemon.
2024-10-24T13:37:05.350737+00:00 box-20241024 fwupdmgr[28249]: Updating lvfs
2024-10-24T13:37:06.272215+00:00 box-20241024 fwupdmgr[28249]: Successfully downloaded new metadata: 0 local devices supported
2024-10-24T13:37:06.275402+00:00 box-20241024 systemd[1]: fwupd-refresh.service: Deactivated successfully.
2024-10-24T13:37:06.275769+00:00 box-20241024 systemd[1]: Finished fwupd-refresh.service - Refresh fwupd metadata and update motd.
2024-10-24T13:39:01.442079+00:00 box-20241024 CRON[28298]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
2024-10-24T13:39:01.453046+00:00 box-20241024 systemd[1]: Starting phpsessionclean.service - Clean php session files...
2024-10-24T13:39:01.558813+00:00 box-20241024 systemd[1]: phpsessionclean.service: Deactivated successfully.
2024-10-24T13:39:01.558935+00:00 box-20241024 systemd[1]: Finished phpsessionclean.service - Clean php session files.
2024-10-24T13:40:01.919181+00:00 box-20241024 systemd[1]: Starting sysstat-collect.service - system activity accounting tool...
2024-10-24T13:40:01.940882+00:00 box-20241024 systemd[1]: sysstat-collect.service: Deactivated successfully.
2024-10-24T13:40:01.941063+00:00 box-20241024 systemd[1]: Finished sysstat-collect.service - system activity accounting tool.
2024-10-24T13:44:01.157696+00:00 box-20241024 python3[27674]: 2024-10-24 09:44:01,156 INFO sqlalchemy.engine.Engine ROLLBACK
2024-10-24T13:45:01.679872+00:00 box-20241024 CRON[28412]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
2024-10-24T13:46:46.805840+00:00 box-20241024 python3[27674]: 2024-10-24 09:46:46,804 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2024-10-24T13:46:46.806373+00:00 box-20241024 python3[27674]: 2024-10-24 09:46:46,805 INFO sqlalchemy.engine.Engine SELECT media.path AS media_path, media.duration AS media_duration, media.live_status AS media_live_status
2024-10-24T13:46:46.806402+00:00 box-20241024 python3[27674]: FROM media
2024-10-24T13:46:46.806445+00:00 box-20241024 python3[27674]: WHERE media.path LIKE ? AND (media.error IS NULL OR media.error = ?)
2024-10-24T13:46:46.806461+00:00 box-20241024 python3[27674]: 2024-10-24 09:46:46,805 INFO sqlalchemy.engine.Engine [cached since 1443s ago] ('http%', '')
2024-10-24T13:46:46.818071+00:00 box-20241024 python3[27674]: 2024-10-24 09:46:46,817 INFO sqlalchemy.engine.Engine SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error
2024-10-24T13:46:46.818228+00:00 box-20241024 python3[27674]: FROM media
2024-10-24T13:46:46.818242+00:00 box-20241024 python3[27674]: WHERE ? LIKE (? || media.extractor_id || ?)
2024-10-24T13:46:46.818257+00:00 box-20241024 python3[27674]:  LIMIT ? OFFSET ?
2024-10-24T13:46:46.818274+00:00 box-20241024 python3[27674]: 2024-10-24 09:46:46,817 INFO sqlalchemy.engine.Engine [cached since 1443s ago] ('https://www.youtube.com/watch?v=hnveeZUk6Rg', '%', '%', 1, 0)
2024-10-24T13:46:46.818827+00:00 box-20241024 python3[27674]: 2024-10-24 09:46:46,818 INFO sqlalchemy.engine.Engine COMMIT
2024-10-24T13:47:33.083962+00:00 box-20241024 python3[27674]: 2024-10-24 09:47:33,083 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2024-10-24T13:47:33.084098+00:00 box-20241024 python3[27674]: 2024-10-24 09:47:33,084 INFO sqlalchemy.engine.Engine SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error
2024-10-24T13:47:33.084153+00:00 box-20241024 python3[27674]: FROM media
2024-10-24T13:47:33.084171+00:00 box-20241024 python3[27674]: WHERE media.webpath = ? AND media.path NOT LIKE ?
2024-10-24T13:47:33.084192+00:00 box-20241024 python3[27674]:  LIMIT ? OFFSET ?
2024-10-24T13:47:33.084211+00:00 box-20241024 python3[27674]: 2024-10-24 09:47:33,084 INFO sqlalchemy.engine.Engine [cached since 1458s ago] ('https://www.youtube.com/watch?v=hnveeZUk6Rg', 'http%', 1, 0)
2024-10-24T13:47:33.122706+00:00 box-20241024 python3[27674]: 2024-10-24 09:47:33,122 INFO sqlalchemy.engine.Engine SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS media_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_modified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath AS media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_uploaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error
2024-10-24T13:47:33.122791+00:00 box-20241024 python3[27674]: FROM media
2024-10-24T13:47:33.122823+00:00 box-20241024 python3[27674]: WHERE media.extractor_id = ? AND media.path LIKE ?
2024-10-24T13:47:33.122851+00:00 box-20241024 python3[27674]:  LIMIT ? OFFSET ?
2024-10-24T13:47:33.122868+00:00 box-20241024 python3[27674]: 2024-10-24 09:47:33,122 INFO sqlalchemy.engine.Engine [cached since 1458s ago] ('hnveeZUk6Rg', '%Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg]%', 1, 0)
2024-10-24T13:47:33.123421+00:00 box-20241024 python3[27674]: 2024-10-24 09:47:33,123 INFO sqlalchemy.engine.Engine SELECT captions.rowid AS captions_rowid, captions.media_id AS captions_media_id, captions.time AS captions_time, captions.text AS captions_text
2024-10-24T13:47:33.123458+00:00 box-20241024 python3[27674]: FROM captions
2024-10-24T13:47:33.123470+00:00 box-20241024 python3[27674]: WHERE captions.media_id = ?
2024-10-24T13:47:33.123487+00:00 box-20241024 python3[27674]:  LIMIT ? OFFSET ?
2024-10-24T13:47:33.123501+00:00 box-20241024 python3[27674]: 2024-10-24 09:47:33,123 INFO sqlalchemy.engine.Engine [cached since 1458s ago] (2, 1, 0)
2024-10-24T13:47:33.166388+00:00 box-20241024 python3[27674]: 2024-10-24 09:47:33,166 INFO sqlalchemy.engine.Engine UPDATE media SET path=?, webpath=? WHERE media.id = ?
2024-10-24T13:47:33.166464+00:00 box-20241024 python3[27674]: 2024-10-24 09:47:33,166 INFO sqlalchemy.engine.Engine [cached since 1458s ago] ('/library/calibre-web/Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020) (3)/Norah Jones - Mini Concert - Happy Birthda - Norah Jones All A Dream.mp4', 'https://www.youtube.com/watch?v=hnveeZUk6Rg&timestamp=1729777653', 2)
2024-10-24T13:47:33.166736+00:00 box-20241024 python3[27674]: 2024-10-24 09:47:33,166 INFO sqlalchemy.engine.Engine COMMIT
2024-10-24T13:50:03.581195+00:00 box-20241024 systemd[1]: Starting sysstat-collect.service - system activity accounting tool...
2024-10-24T13:50:03.604876+00:00 box-20241024 systemd[1]: sysstat-collect.service: Deactivated successfully.
2024-10-24T13:50:03.605065+00:00 box-20241024 systemd[1]: Finished sysstat-collect.service - system activity accounting tool.

Calibre-Web log

[2024-10-24 08:55:49,579] DEBUG {cps.config_sql:388} _ConfigSQL updating storage
[2024-10-24 08:55:49,592]  INFO {cps:171} *** "greenlet" version does not meet the requirements. Should: <3.1.0, Found: 3.1.1, please consider installing requ
ired version ***
[2024-10-24 08:55:49,592]  INFO {cps:180} Starting Calibre Web...
[2024-10-24 08:55:49,596] DEBUG {cps.services:26} Cannot import goodreads, showing authors-metadata will not work: No module named 'goodreads'
[2024-10-24 08:55:49,597] DEBUG {cps.services:34} Cannot import simpleldap, logging in with ldap will not work: No module named 'flask_simpleldap'
[2024-10-24 08:55:49,632] DEBUG {cps.services:49} Cannot import gmail, sending books via Gmail Oauth2 Verification will not work: No module named 'google_auth
_oauthlib'
[2024-10-24 08:55:49,641]  WARN {py.warnings:110} /usr/local/calibre-web-py3/lib/python3.12/site-packages/flask_limiter/extension.py:333: UserWarning: Using t
he in-memory storage for tracking rate limits as no storage was explicitly specified. This is not recommended for production use. See: https://flask-limiter.r
eadthedocs.io#configuring-a-storage-backend for documentation about configuring the storage backend.
  warnings.warn(

[2024-10-24 08:55:49,730] DEBUG {cps.gdriveutils:83} Cannot import pydrive, httplib2, using gdrive will not work: No module named 'pydrive'
[2024-10-24 08:55:49,812]  INFO {apscheduler.scheduler:181} Scheduler started
[2024-10-24 08:55:49,812]  INFO {apscheduler.scheduler:895} Added job "delete temp" to job store "default"
[2024-10-24 08:55:49,812]  INFO {apscheduler.scheduler:895} Added job "end scheduled task" to job store "default"
[2024-10-24 08:55:49,813]  INFO {apscheduler.scheduler:895} Added job "immediately delete temp" to job store "default"
[2024-10-24 08:55:49,822]  INFO {apscheduler.executors.default:123} Running job "immediately delete temp (trigger: date[2024-10-24 08:55:49 EDT], next run at:
 2024-10-24 08:55:49 EDT)" (scheduled at 2024-10-24 08:55:49.813013-04:00)
[2024-10-24 08:55:49,823]  INFO {apscheduler.scheduler:641} Removed job 0915d83faa444d9697ca11307a8fc407
[2024-10-24 08:55:49,826] DEBUG {cps.services.worker:91} Add Task for user: System - Clean up
[2024-10-24 08:55:49,826]  INFO {apscheduler.executors.default:144} Job "immediately delete temp (trigger: date[2024-10-24 08:55:49 EDT], next run at: 2024-10
-24 08:55:49 EDT)" executed successfully
[2024-10-24 08:55:49,826] DEBUG {cps.tasks.clean:43} Deleted expired session_keys
[2024-10-24 08:55:49,853]  WARN {py.warnings:110} /usr/local/calibre-web-py3/cps/cw_advocate/api.py:113: SyntaxWarning: invalid escape sequence '\*'
  """Sends a GET request.

[2024-10-24 08:55:49,853]  WARN {py.warnings:110} /usr/local/calibre-web-py3/cps/cw_advocate/api.py:125: SyntaxWarning: invalid escape sequence '\*'
  '''def options(url, **kwargs):

[2024-10-24 08:55:49,910] DEBUG {cps.comic:46} Cannot import comicapi, extracting comic metadata will not work: No module named 'comicapi'
[2024-10-24 08:55:49,911] DEBUG {cps.comic:53} Cannot import rarfile, extracting cover files from rar files will not work: No module named 'rarfile'
[2024-10-24 08:55:49,912] DEBUG {cps.comic:59} Cannot import py7zr, extracting cover files from CB7 files will not work: No module named 'py7zr'
[2024-10-24 08:55:49,950] DEBUG {cps.uploader:85} Cannot import mutagen, extracting audio metadata will not work: No module named 'mutagen'
[2024-10-24 08:55:49,961] DEBUG {cps.admin:83} Cannot import Flask-Dance, login with Oauth will not work: No module named 'flask_dance'
[2024-10-24 08:55:49,964] DEBUG {cps.gdrive:44} Cannot import googleapiclient, using GDrive will not work: No module named 'googleapiclient'
[2024-10-24 08:55:50,015] DEBUG {cps.search_metadata:61} Import error for metadata source: scholar - No module named 'scholarly'
[2024-10-24 08:55:50,016] DEBUG {cps.search_metadata:61} Import error for metadata source: amazon - No module named 'bs4'
[2024-10-24 08:55:50,020] DEBUG {cps.search_metadata:61} Import error for metadata source: douban - No module named 'html2text'
[2024-10-24 08:55:50,027] DEBUG {cps.search_metadata:61} Import error for metadata source: lubimyczytac - No module named 'dateutil'
[2024-10-24 08:55:50,069]  INFO {cps.server:268} Starting Tornado server on :8083
[2024-10-24 09:05:36,507] DEBUG {cps.web:1436} You are now logged in as: 'Admin'
[2024-10-24 09:05:36,525] DEBUG {cps.ub:84} Login and store session : a7899209591e4087a79076987ee12438aa0d1723a0e9bd319076aab169fe023c025e53db778d7e5b96138d0a
1d038b48801c81174ca99466fe9ae7d93e978cf8
[2024-10-24 09:06:46,532] DEBUG {cps.services.worker:91} Add Task for user: Admin - Metadata fetch task for https://www.youtube.com/watch?v=6jYtRQ2tHGg
[2024-10-24 09:06:46,537]  INFO {cps.tasks.metadata_extract:155} Starting to fetch metadata for URL: https://www.youtube.com/watch?v=6jYtRQ2tHGg
[2024-10-24 09:06:49,791] DEBUG {cps.services.worker:91} Add Task for user: Admin - Download task for https://www.youtube.com/watch?v=6jYtRQ2tHGg
[2024-10-24 09:06:49,792]  INFO {cps.tasks.download:43} Subprocess args: ['lb-wrapper', 'dl', 'https://www.youtube.com/watch?v=6jYtRQ2tHGg']
[2024-10-24 09:07:25,863]  INFO {cps.editbooks:235} Received metadata request: ImmutableMultiDict([('requested_file', '/library/downloads/calibre-web/Youtube/
NPR Music/Norah Jones： Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4'), ('current_user_name', 'Admin')])
[2024-10-24 09:07:25,863]  INFO {cps.editbooks:237} Requested file: /library/downloads/calibre-web/Youtube/NPR Music/Norah Jones： Tiny Desk Concert_1.64M_[6j
YtRQ2tHGg].mp4
[2024-10-24 09:07:25,863]  INFO {cps.editbooks:242} Processing file: <_io.BufferedReader name='/library/downloads/calibre-web/Youtube/NPR Music/Norah Jones： 
Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4'>
[2024-10-24 09:07:25,918] DEBUG {cps.uploader:392} Temporary file: /tmp/calibre_web/0ff8266c85d75623c739fec8c600bb9f
[2024-10-24 09:07:25,940]  WARN {py.warnings:110} /usr/local/calibre-web-py3/cps/editbooks.py:1564: SAWarning: Object of type <Books> not in session, add oper
ation along 'Authors.books' won't proceed (This warning originated from the Session 'autoflush' process, which was invoked automatically in response to a user
-initiated operation.)
  db_element = db_session.query(db_object).filter((func.lower(db_filter).ilike(add_element))).all()

[2024-10-24 09:07:25,955] DEBUG {cps.helper:536} Moving title: /tmp/calibre_web/0ff8266c85d75623c739fec8c600bb9f to /library/calibre-web/NPR Music/Norah Jones
_ Tiny Desk Concert (1)
[2024-10-24 09:07:25,963]  INFO {cps.tasks.download:115} Successfully sent the requested file to http://192.168.64.43/books/meta
[2024-10-24 09:07:25,968]  INFO {cps.tasks.download:138} Download task for https://www.youtube.com/watch?v=6jYtRQ2tHGg completed successfully
[2024-10-24 09:18:36,696]  INFO {cps.server:319} webserver stop (restart=False)
[2024-10-24 09:18:36,702]  INFO {apscheduler.scheduler:212} Scheduler has been shut down
[2024-10-24 09:18:36,706]  INFO {cps.server:298} Performing shutdown of Calibre-Web
[2024-10-24 09:18:38,494]  INFO {cps:171} *** "greenlet" version does not meet the requirements. Should: <3.1.0, Found: 3.1.1, please consider installing requ
ired version ***
[2024-10-24 09:18:38,495]  INFO {cps:180} Starting Calibre Web...
[2024-10-24 09:18:38,504]  WARN {py.warnings:110} /usr/local/calibre-web-py3/lib/python3.12/site-packages/flask_limiter/extension.py:333: UserWarning: Using t
he in-memory storage for tracking rate limits as no storage was explicitly specified. This is not recommended for production use. See: https://flask-limiter.r
eadthedocs.io#configuring-a-storage-backend for documentation about configuring the storage backend.
  warnings.warn(

[2024-10-24 09:18:38,581] DEBUG {cps.gdriveutils:83} Cannot import pydrive, httplib2, using gdrive will not work: No module named 'pydrive'
[2024-10-24 09:18:38,645]  INFO {apscheduler.scheduler:181} Scheduler started
[2024-10-24 09:18:38,646]  INFO {apscheduler.scheduler:895} Added job "delete temp" to job store "default"
[2024-10-24 09:18:38,646]  INFO {apscheduler.scheduler:895} Added job "end scheduled task" to job store "default"
[2024-10-24 09:18:38,646]  INFO {apscheduler.scheduler:895} Added job "immediately delete temp" to job store "default"
[2024-10-24 09:18:38,646]  INFO {apscheduler.executors.default:123} Running job "immediately delete temp (trigger: date[2024-10-24 09:18:38 EDT], next run at:
 2024-10-24 09:18:38 EDT)" (scheduled at 2024-10-24 09:18:38.646490-04:00)
[2024-10-24 09:18:38,647]  INFO {apscheduler.scheduler:641} Removed job 6ae058d6b07645d2bc75de3689e50688
[2024-10-24 09:18:38,647] DEBUG {cps.services.worker:91} Add Task for user: System - Clean up
[2024-10-24 09:18:38,647]  INFO {apscheduler.executors.default:144} Job "immediately delete temp (trigger: date[2024-10-24 09:18:38 EDT], next run at: 2024-10
-24 09:18:38 EDT)" executed successfully
[2024-10-24 09:18:38,648] DEBUG {cps.tasks.clean:43} Deleted expired session_keys
[2024-10-24 09:18:38,706] DEBUG {cps.comic:46} Cannot import comicapi, extracting comic metadata will not work: No module named 'comicapi'
[2024-10-24 09:18:38,707] DEBUG {cps.comic:53} Cannot import rarfile, extracting cover files from rar files will not work: No module named 'rarfile'
[2024-10-24 09:18:38,707] DEBUG {cps.comic:59} Cannot import py7zr, extracting cover files from CB7 files will not work: No module named 'py7zr'
[2024-10-24 09:18:38,754] DEBUG {cps.uploader:86} Cannot import mutagen, extracting audio metadata will not work: No module named 'mutagen'
[2024-10-24 09:18:38,764] DEBUG {cps.admin:83} Cannot import Flask-Dance, login with Oauth will not work: No module named 'flask_dance'
[2024-10-24 09:18:38,765] DEBUG {cps.gdrive:44} Cannot import googleapiclient, using GDrive will not work: No module named 'googleapiclient'
[2024-10-24 09:18:38,814] DEBUG {cps.search_metadata:61} Import error for metadata source: scholar - No module named 'scholarly'
[2024-10-24 09:18:38,815] DEBUG {cps.search_metadata:61} Import error for metadata source: amazon - No module named 'bs4'
[2024-10-24 09:18:38,818] DEBUG {cps.search_metadata:61} Import error for metadata source: douban - No module named 'html2text'
[2024-10-24 09:18:38,833] DEBUG {cps.search_metadata:61} Import error for metadata source: lubimyczytac - No module named 'dateutil'
[2024-10-24 09:18:38,873]  INFO {cps.server:268} Starting Tornado server on :8083
[2024-10-24 09:19:01,083]  INFO {cps.xb:130} XKLBDB instance created with database file: /library/calibre-web/xklb-metadata.db
[2024-10-24 09:19:01,084]  INFO {cps.glue_db:40} Creating new glue database at /library/calibre-web/iiab-glue.db
[2024-10-24 09:19:01,122]  INFO {cps.glue_db:29} GlueDB instance created with database file: /library/calibre-web/iiab-glue.db
[2024-10-24 09:19:01,123]  INFO {sqlalchemy.engine.Engine:2701} BEGIN (implicit)
[2024-10-24 09:19:01,130]  INFO {sqlalchemy.engine.Engine:1846} SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time A
S captions_time 
FROM captions 
WHERE captions.text LIKE ?
[2024-10-24 09:19:01,131]  INFO {sqlalchemy.engine.Engine:1846} [generated in 0.00017s] ('%performance%',)
[2024-10-24 09:20:55,358]  INFO {cps.server:319} webserver stop (restart=False)
[2024-10-24 09:20:55,362]  INFO {apscheduler.scheduler:212} Scheduler has been shut down
[2024-10-24 09:20:55,364]  INFO {cps.server:298} Performing shutdown of Calibre-Web
[2024-10-24 09:20:56,778]  INFO {cps:171} *** "greenlet" version does not meet the requirements. Should: <3.1.0, Found: 3.1.1, please consider installing requ
ired version ***
[2024-10-24 09:20:56,778]  INFO {cps:180} Starting Calibre Web...
[2024-10-24 09:20:56,807]  WARN {py.warnings:110} /usr/local/calibre-web-py3/lib/python3.12/site-packages/flask_limiter/extension.py:333: UserWarning: Using t
he in-memory storage for tracking rate limits as no storage was explicitly specified. This is not recommended for production use. See: https://flask-limiter.r
eadthedocs.io#configuring-a-storage-backend for documentation about configuring the storage backend.
  warnings.warn(

[2024-10-24 09:20:56,840] DEBUG {cps.gdriveutils:83} Cannot import pydrive, httplib2, using gdrive will not work: No module named 'pydrive'
[2024-10-24 09:20:56,884]  INFO {apscheduler.scheduler:181} Scheduler started
[2024-10-24 09:20:56,884]  INFO {apscheduler.scheduler:895} Added job "delete temp" to job store "default"
[2024-10-24 09:20:56,884]  INFO {apscheduler.scheduler:895} Added job "end scheduled task" to job store "default"
[2024-10-24 09:20:56,884]  INFO {apscheduler.scheduler:895} Added job "immediately delete temp" to job store "default"
[2024-10-24 09:20:56,885]  INFO {apscheduler.executors.default:123} Running job "immediately delete temp (trigger: date[2024-10-24 09:20:56 EDT], next run at:
 2024-10-24 09:20:56 EDT)" (scheduled at 2024-10-24 09:20:56.884895-04:00)
[2024-10-24 09:20:56,885]  INFO {apscheduler.scheduler:641} Removed job 7ab6f996ab064dc8a30da63d026f5d70
[2024-10-24 09:20:56,886] DEBUG {cps.services.worker:91} Add Task for user: System - Clean up
[2024-10-24 09:20:56,886]  INFO {apscheduler.executors.default:144} Job "immediately delete temp (trigger: date[2024-10-24 09:20:56 EDT], next run at: 2024-10
-24 09:20:56 EDT)" executed successfully
[2024-10-24 09:20:56,886] DEBUG {cps.tasks.clean:43} Deleted expired session_keys
[2024-10-24 09:20:56,933] DEBUG {cps.comic:46} Cannot import comicapi, extracting comic metadata will not work: No module named 'comicapi'
[2024-10-24 09:20:56,934] DEBUG {cps.comic:53} Cannot import rarfile, extracting cover files from rar files will not work: No module named 'rarfile'
[2024-10-24 09:20:56,934] DEBUG {cps.comic:59} Cannot import py7zr, extracting cover files from CB7 files will not work: No module named 'py7zr'
[2024-10-24 09:20:56,963] DEBUG {cps.uploader:86} Cannot import mutagen, extracting audio metadata will not work: No module named 'mutagen'
[2024-10-24 09:20:56,973] DEBUG {cps.admin:83} Cannot import Flask-Dance, login with Oauth will not work: No module named 'flask_dance'
[2024-10-24 09:20:56,974] DEBUG {cps.gdrive:44} Cannot import googleapiclient, using GDrive will not work: No module named 'googleapiclient'
[2024-10-24 09:20:57,000] DEBUG {cps.search_metadata:61} Import error for metadata source: scholar - No module named 'scholarly'
[2024-10-24 09:20:57,000] DEBUG {cps.search_metadata:61} Import error for metadata source: amazon - No module named 'bs4'
[2024-10-24 09:20:57,002] DEBUG {cps.search_metadata:61} Import error for metadata source: douban - No module named 'html2text'
[2024-10-24 09:20:57,005] DEBUG {cps.search_metadata:61} Import error for metadata source: lubimyczytac - No module named 'dateutil'
[2024-10-24 09:20:57,040]  INFO {cps.server:268} Starting Tornado server on :8083
[2024-10-24 09:21:15,509]  INFO {sqlalchemy.engine.Engine:2701} BEGIN (implicit)
[2024-10-24 09:21:15,521]  INFO {sqlalchemy.engine.Engine:1846} PRAGMA main.table_info("media")
[2024-10-24 09:21:15,521]  INFO {sqlalchemy.engine.Engine:1846} [raw sql] ()
[2024-10-24 09:21:15,522]  INFO {sqlalchemy.engine.Engine:1846} PRAGMA temp.table_info("media")
[2024-10-24 09:21:15,522]  INFO {sqlalchemy.engine.Engine:1846} [raw sql] ()
[2024-10-24 09:21:15,523]  INFO {sqlalchemy.engine.Engine:1846} PRAGMA main.table_info("captions")
[2024-10-24 09:21:15,523]  INFO {sqlalchemy.engine.Engine:1846} [raw sql] ()
[2024-10-24 09:21:15,524]  INFO {sqlalchemy.engine.Engine:1846} PRAGMA temp.table_info("captions")
[2024-10-24 09:21:15,524]  INFO {sqlalchemy.engine.Engine:1846} [raw sql] ()
[2024-10-24 09:21:15,525]  INFO {sqlalchemy.engine.Engine:1846} PRAGMA main.table_info("playlists")
[2024-10-24 09:21:15,525]  INFO {sqlalchemy.engine.Engine:1846} [raw sql] ()
[2024-10-24 09:21:15,525]  INFO {sqlalchemy.engine.Engine:1846} PRAGMA temp.table_info("playlists")
[2024-10-24 09:21:15,525]  INFO {sqlalchemy.engine.Engine:1846} [raw sql] ()
[2024-10-24 09:21:15,526]  INFO {sqlalchemy.engine.Engine:1846} 
CREATE TABLE media (
	id INTEGER NOT NULL, 
	time_deleted INTEGER, 
	playlists_id INTEGER, 
	size INTEGER, 
	duration INTEGER, 
	time_created INTEGER, 
	time_modified INTEGER, 
	time_downloaded INTEGER, 
	fps INTEGER, 
	view_count INTEGER, 
	path TEXT, 
	webpath TEXT, 
	extractor_id TEXT, 
	title TEXT, 
	uploader TEXT, 
	time_uploaded INTEGER, 
	width INTEGER, 
	height INTEGER, 
	live_status TEXT, 
	type TEXT, 
	video_codecs TEXT, 
	audio_codecs TEXT, 
	subtitle_codecs TEXT, 
	other_codecs TEXT, 
	video_count INTEGER, 
	audio_count INTEGER, 
	chapter_count INTEGER, 
	other_count INTEGER, 
	language TEXT, 
	subtitle_count INTEGER, 
	download_attempts INTEGER, 
	error TEXT, 
	PRIMARY KEY (id)
)


[2024-10-24 09:21:15,527]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00078s] ()
[2024-10-24 09:21:15,565]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_media_duration ON media (duration)
[2024-10-24 09:21:15,565]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00016s] ()
[2024-10-24 09:21:15,573]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_media_playlists_id ON media (playlists_id)
[2024-10-24 09:21:15,573]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00008s] ()
[2024-10-24 09:21:15,580]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_media_live_status ON media (live_status)
[2024-10-24 09:21:15,580]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00010s] ()
[2024-10-24 09:21:15,585]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_media_time_created ON media (time_created)
[2024-10-24 09:21:15,585]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00005s] ()
[2024-10-24 09:21:15,590]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_media_time_modified ON media (time_modified)
[2024-10-24 09:21:15,590]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00009s] ()
[2024-10-24 09:21:15,593]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_media_time_downloaded ON media (time_downloaded)
[2024-10-24 09:21:15,593]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00007s] ()
[2024-10-24 09:21:15,596]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_media_time_uploaded ON media (time_uploaded)
[2024-10-24 09:21:15,596]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00005s] ()
[2024-10-24 09:21:15,599]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_media_fps ON media (fps)
[2024-10-24 09:21:15,599]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00005s] ()
[2024-10-24 09:21:15,603]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_media_view_count ON media (view_count)
[2024-10-24 09:21:15,603]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00007s] ()
[2024-10-24 09:21:15,606]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_media_time_deleted ON media (time_deleted)
[2024-10-24 09:21:15,606]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00007s] ()
[2024-10-24 09:21:15,610]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_media_uploader ON media (uploader)
[2024-10-24 09:21:15,610]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00007s] ()
[2024-10-24 09:21:15,613]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_media_id ON media (id)
[2024-10-24 09:21:15,613]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00007s] ()
[2024-10-24 09:21:15,617]  INFO {sqlalchemy.engine.Engine:1846} CREATE UNIQUE INDEX idx_media_path ON media (path)
[2024-10-24 09:21:15,617]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00005s] ()
[2024-10-24 09:21:15,620]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_media_size ON media (size)
[2024-10-24 09:21:15,620]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00005s] ()
[2024-10-24 09:21:15,624]  INFO {sqlalchemy.engine.Engine:1846} 
CREATE TABLE playlists (
	id INTEGER NOT NULL, 
	time_modified INTEGER, 
	time_deleted INTEGER, 
	time_created INTEGER, 
	hours_update_delay INTEGER, 
	path TEXT, 
	extractor_key TEXT, 
	profile TEXT, 
	extractor_config TEXT, 
	extractor_playlist_id TEXT, 
	title TEXT, 
	uploader TEXT, 
	PRIMARY KEY (id)
)


[2024-10-24 09:21:15,624]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00007s] ()
[2024-10-24 09:21:15,629]  INFO {sqlalchemy.engine.Engine:1846} CREATE UNIQUE INDEX idx_playlists_path ON playlists (path)
[2024-10-24 09:21:15,629]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00006s] ()
[2024-10-24 09:21:15,633]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_playlists_hours_update_delay ON playlists (hours_update_delay)
[2024-10-24 09:21:15,633]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00006s] ()
[2024-10-24 09:21:15,636]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_playlists_extractor_config ON playlists (extractor_config)
[2024-10-24 09:21:15,636]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00006s] ()
[2024-10-24 09:21:15,640]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_playlists_id ON playlists (id)
[2024-10-24 09:21:15,640]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00007s] ()
[2024-10-24 09:21:15,643]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_playlists_time_created ON playlists (time_created)
[2024-10-24 09:21:15,643]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00006s] ()
[2024-10-24 09:21:15,647]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_playlists_time_deleted ON playlists (time_deleted)
[2024-10-24 09:21:15,647]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00007s] ()
[2024-10-24 09:21:15,650]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_playlists_uploader ON playlists (uploader)
[2024-10-24 09:21:15,650]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00005s] ()
[2024-10-24 09:21:15,654]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_playlists_profile ON playlists (profile)
[2024-10-24 09:21:15,654]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00005s] ()
[2024-10-24 09:21:15,658]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_playlists_extractor_key ON playlists (extractor_key)
[2024-10-24 09:21:15,658]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00005s] ()
[2024-10-24 09:21:15,661]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_playlists_time_modified ON playlists (time_modified)
[2024-10-24 09:21:15,661]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00006s] ()
[2024-10-24 09:21:15,665]  INFO {sqlalchemy.engine.Engine:1846} 
CREATE TABLE captions (
	rowid INTEGER NOT NULL, 
	media_id INTEGER, 
	time INTEGER, 
	text TEXT, 
	PRIMARY KEY (rowid), 
	FOREIGN KEY(media_id) REFERENCES media (id)
)


[2024-10-24 09:21:15,665]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00007s] ()
[2024-10-24 09:21:15,669]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_captions_time ON captions (time)
[2024-10-24 09:21:15,669]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00005s] ()
[2024-10-24 09:21:15,672]  INFO {sqlalchemy.engine.Engine:1846} CREATE INDEX idx_captions_media_id ON captions (media_id)
[2024-10-24 09:21:15,672]  INFO {sqlalchemy.engine.Engine:1846} [no key 0.00005s] ()
[2024-10-24 09:21:15,676]  INFO {sqlalchemy.engine.Engine:2707} COMMIT
[2024-10-24 09:21:15,676]  INFO {cps.xb:130} XKLBDB instance created with database file: /library/calibre-web/xklb-metadata.db
[2024-10-24 09:21:15,676]  INFO {cps.glue_db:29} GlueDB instance created with database file: /library/calibre-web/iiab-glue.db
[2024-10-24 09:21:15,677]  INFO {sqlalchemy.engine.Engine:2701} BEGIN (implicit)
[2024-10-24 09:21:15,681]  INFO {sqlalchemy.engine.Engine:1846} SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time A
S captions_time 
FROM captions 
WHERE captions.text LIKE ?
[2024-10-24 09:21:15,681]  INFO {sqlalchemy.engine.Engine:1846} [generated in 0.00011s] ('%performance%',)
[2024-10-24 09:21:54,148]  INFO {sqlalchemy.engine.Engine:1846} SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time A
S captions_time 
FROM captions 
WHERE captions.text LIKE ?
[2024-10-24 09:21:54,149]  INFO {sqlalchemy.engine.Engine:1846} [cached since 38.47s ago] ('%performance%',)
[2024-10-24 09:22:12,326] DEBUG {cps.services.worker:91} Add Task for user: Admin - Metadata fetch task for https://www.youtube.com/watch?v=6jYtRQ2tHGg
[2024-10-24 09:22:13,258]  INFO {cps.tasks.metadata_extract:150} Starting metadata extraction task for URL: https://www.youtube.com/watch?v=6jYtRQ2tHGg
[2024-10-24 09:22:13,259] DEBUG {cps.tasks.metadata_extract:43} Executing subprocess with args: ['lb-wrapper', 'tubeadd', 'https://www.youtube.com/watch?v=6jY
tRQ2tHGg']
[2024-10-24 09:22:15,858]  INFO {sqlalchemy.engine.Engine:2704} ROLLBACK
[2024-10-24 09:22:15,859] ERROR {cps.tasks.metadata_extract:197} An error occurred during the metadata extraction task: A transaction is already begun on this
 Session.
[2024-10-24 09:22:41,366] DEBUG {cps.services.worker:91} Add Task for user: Admin - Metadata fetch task for https://www.youtube.com/watch?v=6jYtRQ2tHGg
[2024-10-24 09:22:41,367]  INFO {cps.tasks.metadata_extract:150} Starting metadata extraction task for URL: https://www.youtube.com/watch?v=6jYtRQ2tHGg
[2024-10-24 09:22:41,368] DEBUG {cps.tasks.metadata_extract:43} Executing subprocess with args: ['lb-wrapper', 'tubeadd', 'https://www.youtube.com/watch?v=6jY
tRQ2tHGg']
[2024-10-24 09:22:43,627] DEBUG {cps.services.xb_utils:58} Fetching requested URLs from the database.
[2024-10-24 09:22:43,628]  INFO {sqlalchemy.engine.Engine:2701} BEGIN (implicit)
[2024-10-24 09:22:43,630]  INFO {sqlalchemy.engine.Engine:1846} SELECT media.path AS media_path, media.duration AS media_duration, media.live_status AS media_
live_status 
FROM media 
WHERE media.path LIKE ? AND (media.error IS NULL OR media.error = ?)
[2024-10-24 09:22:43,630]  INFO {sqlalchemy.engine.Engine:1846} [generated in 0.00013s] ('http%', '')
[2024-10-24 09:22:43,631]  INFO {cps.services.xb_utils:70} Fetched 1 requested URLs.
[2024-10-24 09:22:43,631] DEBUG {cps.services.xb_utils:115} Getting extractor ID for URL: https://www.youtube.com/watch?v=6jYtRQ2tHGg
[2024-10-24 09:22:43,633]  INFO {sqlalchemy.engine.Engine:1846} SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS m
edia_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_mod
ified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath A
S media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_upl
oaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media
_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video
_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media
.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error 
FROM media 
WHERE ? LIKE (? || media.extractor_id || ?)
 LIMIT ? OFFSET ?
[2024-10-24 09:22:43,633]  INFO {sqlalchemy.engine.Engine:1846} [generated in 0.00014s] ('https://www.youtube.com/watch?v=6jYtRQ2tHGg', '%', '%', 1, 0)
[2024-10-24 09:22:43,633]  INFO {cps.services.xb_utils:121} Extractor ID found: 6jYtRQ2tHGg
[2024-10-24 09:22:43,633] DEBUG {cps.tasks.metadata_extract:108} Adding download tasks to the worker thread.
[2024-10-24 09:22:43,634] DEBUG {cps.services.worker:91} Add Task for user: Admin - Download task for https://www.youtube.com/watch?v=6jYtRQ2tHGg
[2024-10-24 09:22:43,634]  INFO {cps.tasks.metadata_extract:145} Download tasks added to the worker thread.
[2024-10-24 09:22:43,634]  INFO {sqlalchemy.engine.Engine:2707} COMMIT
[2024-10-24 09:22:43,634]  INFO {cps.tasks.metadata_extract:193} Metadata extraction task for https://www.youtube.com/watch?v=6jYtRQ2tHGg completed successful
ly.
[2024-10-24 09:22:43,634]  INFO {cps.tasks.download:40} Starting download task for URL: https://www.youtube.com/watch?v=6jYtRQ2tHGg
[2024-10-24 09:22:43,634] DEBUG {cps.tasks.download:49} Subprocess args: ['lb-wrapper', 'dl', 'https://www.youtube.com/watch?v=6jYtRQ2tHGg']
[2024-10-24 09:22:43,635] DEBUG {cps.tasks.download:79} Monitoring subprocess for download progress.
[2024-10-24 09:22:45,968] DEBUG {cps.tasks.download:99} Download progress reached 99%.
[2024-10-24 09:23:15,074] DEBUG {cps.tasks.download:120} Post-processing after download.
[2024-10-24 09:23:15,076]  INFO {sqlalchemy.engine.Engine:2701} BEGIN (implicit)
[2024-10-24 09:23:15,079]  INFO {sqlalchemy.engine.Engine:1846} SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS m
edia_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_mod
ified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath A
S media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_upl
oaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media
_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video
_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media
.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error 
FROM media 
WHERE media.webpath = ? AND media.path NOT LIKE ?
 LIMIT ? OFFSET ?
[2024-10-24 09:23:15,079]  INFO {sqlalchemy.engine.Engine:1846} [generated in 0.00033s] ('https://www.youtube.com/watch?v=6jYtRQ2tHGg', 'http%', 1, 0)
[2024-10-24 09:23:15,098]  INFO {cps.editbooks:236} Received metadata request: ImmutableMultiDict([('requested_file', '/library/downloads/calibre-web/Youtube/
NPR Music/Norah Jones： Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4'), ('current_user_name', 'Admin'), ('media_id', '1')])
[2024-10-24 09:23:15,098]  INFO {cps.editbooks:238} Requested file: /library/downloads/calibre-web/Youtube/NPR Music/Norah Jones： Tiny Desk Concert_1.64M_[6j
YtRQ2tHGg].mp4
[2024-10-24 09:23:15,098]  INFO {cps.editbooks:243} Processing file: <_io.BufferedReader name='/library/downloads/calibre-web/Youtube/NPR Music/Norah Jones： 
Tiny Desk Concert_1.64M_[6jYtRQ2tHGg].mp4'>
[2024-10-24 09:23:15,199] DEBUG {cps.uploader:414} Temporary file: /tmp/calibre_web/0ff8266c85d75623c739fec8c600bb9f
[2024-10-24 09:23:15,203]  INFO {sqlalchemy.engine.Engine:1846} SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS m
edia_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_mod
ified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath A
S media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_upl
oaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media
_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video
_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media
.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error 
FROM media 
WHERE media.extractor_id = ? AND media.path LIKE ?
 LIMIT ? OFFSET ?
[2024-10-24 09:23:15,204]  INFO {sqlalchemy.engine.Engine:1846} [generated in 0.00013s] ('6jYtRQ2tHGg', '%Norah Jones： Tiny Desk Concert_1.64M_[6jYtRQ2tHGg]%
', 1, 0)
[2024-10-24 09:23:15,205]  INFO {sqlalchemy.engine.Engine:1846} SELECT captions.rowid AS captions_rowid, captions.media_id AS captions_media_id, captions.time
 AS captions_time, captions.text AS captions_text 
FROM captions 
WHERE captions.media_id = ?
 LIMIT ? OFFSET ?
[2024-10-24 09:23:15,205]  INFO {sqlalchemy.engine.Engine:1846} [generated in 0.00011s] (1, 1, 0)
[2024-10-24 09:23:15,298]  WARN {py.warnings:110} /usr/local/calibre-web-py3/cps/editbooks.py:1568: SAWarning: Object of type <Books> not in session, add oper
ation along 'Authors.books' won't proceed (This warning originated from the Session 'autoflush' process, which was invoked automatically in response to a user
-initiated operation.)
  db_element = db_session.query(db_object).filter((func.lower(db_filter).ilike(add_element))).all()

[2024-10-24 09:23:15,309] DEBUG {cps.helper:536} Moving title: /tmp/calibre_web/0ff8266c85d75623c739fec8c600bb9f to /library/calibre-web/NPR Music/Norah Jones
_ Tiny Desk Concert (2)
[2024-10-24 09:23:15,320]  INFO {cps.services.xb_utils:169} Mapping added: <MediaBooksMapping(media_id=1, book_id=2)>
[2024-10-24 09:23:15,321]  INFO {cps.tasks.download:149} Successfully sent the requested file to http://192.168.64.43/books/meta
[2024-10-24 09:23:15,322]  INFO {sqlalchemy.engine.Engine:1846} UPDATE media SET path=?, webpath=? WHERE media.id = ?
[2024-10-24 09:23:15,322]  INFO {sqlalchemy.engine.Engine:1846} [generated in 0.00012s] ('/library/calibre-web/NPR Music/Norah Jones_ Tiny Desk Concert (2)/No
rah Jones_ Tiny Desk Concert - NPR Music.mp4', 'https://www.youtube.com/watch?v=6jYtRQ2tHGg&timestamp=1729776195', 1)
[2024-10-24 09:23:15,322]  INFO {sqlalchemy.engine.Engine:2707} COMMIT
[2024-10-24 09:23:15,324]  INFO {cps.tasks.download:164} Media entry updated in the database.
[2024-10-24 09:23:15,324]  INFO {cps.tasks.download:67} Download task for https://www.youtube.com/watch?v=6jYtRQ2tHGg completed successfully.
[2024-10-24 09:23:53,489]  INFO {sqlalchemy.engine.Engine:2701} BEGIN (implicit)
[2024-10-24 09:23:53,490]  INFO {sqlalchemy.engine.Engine:1846} SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time A
S captions_time 
FROM captions 
WHERE captions.text LIKE ?
[2024-10-24 09:23:53,490]  INFO {sqlalchemy.engine.Engine:1846} [cached since 157.8s ago] ('%performance%',)
[2024-10-24 09:24:07,097]  INFO {sqlalchemy.engine.Engine:1846} SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time A
S captions_time 
FROM captions 
WHERE captions.text LIKE ?
[2024-10-24 09:24:07,099]  INFO {sqlalchemy.engine.Engine:1846} [cached since 171.4s ago] ('%sacrifice%',)
[2024-10-24 09:43:58,529] DEBUG {cps.services.worker:91} Add Task for user: Admin - Metadata fetch task for https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:43:58,532]  INFO {cps.tasks.metadata_extract:150} Starting metadata extraction task for URL: https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:43:58,533] DEBUG {cps.tasks.metadata_extract:43} Executing subprocess with args: ['lb-wrapper', 'tubeadd', 'https://www.youtube.com/watch?v=hnv
eeZUk6Rg']
[2024-10-24 09:44:01,156]  INFO {sqlalchemy.engine.Engine:2704} ROLLBACK
[2024-10-24 09:44:01,157] ERROR {cps.tasks.metadata_extract:197} An error occurred during the metadata extraction task: A transaction is already begun on this
 Session.
[2024-10-24 09:46:44,456] DEBUG {cps.services.worker:91} Add Task for user: Admin - Metadata fetch task for https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:46:44,457]  INFO {cps.tasks.metadata_extract:150} Starting metadata extraction task for URL: https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:46:44,458] DEBUG {cps.tasks.metadata_extract:43} Executing subprocess with args: ['lb-wrapper', 'tubeadd', 'https://www.youtube.com/watch?v=hnv
eeZUk6Rg']
[2024-10-24 09:46:46,804] DEBUG {cps.services.xb_utils:58} Fetching requested URLs from the database.
[2024-10-24 09:46:46,804]  INFO {sqlalchemy.engine.Engine:2701} BEGIN (implicit)
[2024-10-24 09:46:46,805]  INFO {sqlalchemy.engine.Engine:1846} SELECT media.path AS media_path, media.duration AS media_duration, media.live_status AS media_
live_status 
FROM media 
WHERE media.path LIKE ? AND (media.error IS NULL OR media.error = ?)
[2024-10-24 09:46:46,805]  INFO {sqlalchemy.engine.Engine:1846} [cached since 1443s ago] ('http%', '')
[2024-10-24 09:46:46,806]  INFO {cps.services.xb_utils:70} Fetched 1 requested URLs.
[2024-10-24 09:46:46,806] DEBUG {cps.services.xb_utils:115} Getting extractor ID for URL: https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:46:46,817]  INFO {sqlalchemy.engine.Engine:1846} SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS m
edia_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_mod
ified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath A
S media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_upl
oaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media
_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video
_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media
.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error 
FROM media 
WHERE ? LIKE (? || media.extractor_id || ?)
 LIMIT ? OFFSET ?
[2024-10-24 09:46:46,817]  INFO {sqlalchemy.engine.Engine:1846} [cached since 1443s ago] ('https://www.youtube.com/watch?v=hnveeZUk6Rg', '%', '%', 1, 0)
[2024-10-24 09:46:46,818]  INFO {cps.services.xb_utils:121} Extractor ID found: hnveeZUk6Rg
[2024-10-24 09:46:46,818] DEBUG {cps.tasks.metadata_extract:108} Adding download tasks to the worker thread.
[2024-10-24 09:46:46,818] DEBUG {cps.services.worker:91} Add Task for user: Admin - Download task for https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:46:46,818]  INFO {cps.tasks.metadata_extract:145} Download tasks added to the worker thread.
[2024-10-24 09:46:46,818]  INFO {sqlalchemy.engine.Engine:2707} COMMIT
[2024-10-24 09:46:46,818]  INFO {cps.tasks.metadata_extract:193} Metadata extraction task for https://www.youtube.com/watch?v=hnveeZUk6Rg completed successful
ly.
[2024-10-24 09:46:46,819]  INFO {cps.tasks.download:40} Starting download task for URL: https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:46:46,819] DEBUG {cps.tasks.download:49} Subprocess args: ['lb-wrapper', 'dl', 'https://www.youtube.com/watch?v=hnveeZUk6Rg']
[2024-10-24 09:46:46,819] DEBUG {cps.tasks.download:79} Monitoring subprocess for download progress.
[2024-10-24 09:46:49,367] DEBUG {cps.tasks.download:99} Download progress reached 99%.
[2024-10-24 09:47:33,082] DEBUG {cps.tasks.download:120} Post-processing after download.
[2024-10-24 09:47:33,083]  INFO {sqlalchemy.engine.Engine:2701} BEGIN (implicit)
[2024-10-24 09:47:33,084]  INFO {sqlalchemy.engine.Engine:1846} SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS m
edia_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_mod
ified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath A
S media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_upl
oaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media
_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video
_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media
.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error 
FROM media 
WHERE media.webpath = ? AND media.path NOT LIKE ?
 LIMIT ? OFFSET ?
[2024-10-24 09:47:33,084]  INFO {sqlalchemy.engine.Engine:1846} [cached since 1458s ago] ('https://www.youtube.com/watch?v=hnveeZUk6Rg', 'http%', 1, 0)
[2024-10-24 09:47:33,087]  INFO {cps.editbooks:236} Received metadata request: ImmutableMultiDict([('requested_file', '/library/downloads/calibre-web/Youtube/
Norah Jones All A Dream/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4'), ('current_user_name', 'Admin')
, ('media_id', '2')])
[2024-10-24 09:47:33,087]  INFO {cps.editbooks:238} Requested file: /library/downloads/calibre-web/Youtube/Norah Jones All A Dream/Norah Jones - Mini Concert 
- Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4
[2024-10-24 09:47:33,087]  INFO {cps.editbooks:243} Processing file: <_io.BufferedReader name='/library/downloads/calibre-web/Youtube/Norah Jones All A Dream/
Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg].mp4'>
[2024-10-24 09:47:33,119] DEBUG {cps.uploader:414} Temporary file: /tmp/calibre_web/01e7df17359db91c8ce152b991d8bac9
[2024-10-24 09:47:33,122]  INFO {sqlalchemy.engine.Engine:1846} SELECT media.id AS media_id, media.time_deleted AS media_time_deleted, media.playlists_id AS m
edia_playlists_id, media.size AS media_size, media.duration AS media_duration, media.time_created AS media_time_created, media.time_modified AS media_time_mod
ified, media.time_downloaded AS media_time_downloaded, media.fps AS media_fps, media.view_count AS media_view_count, media.path AS media_path, media.webpath A
S media_webpath, media.extractor_id AS media_extractor_id, media.title AS media_title, media.uploader AS media_uploader, media.time_uploaded AS media_time_upl
oaded, media.width AS media_width, media.height AS media_height, media.live_status AS media_live_status, media.type AS media_type, media.video_codecs AS media
_video_codecs, media.audio_codecs AS media_audio_codecs, media.subtitle_codecs AS media_subtitle_codecs, media.other_codecs AS media_other_codecs, media.video
_count AS media_video_count, media.audio_count AS media_audio_count, media.chapter_count AS media_chapter_count, media.other_count AS media_other_count, media
.language AS media_language, media.subtitle_count AS media_subtitle_count, media.download_attempts AS media_download_attempts, media.error AS media_error 
FROM media 
WHERE media.extractor_id = ? AND media.path LIKE ?
 LIMIT ? OFFSET ?
[2024-10-24 09:47:33,122]  INFO {sqlalchemy.engine.Engine:1846} [cached since 1458s ago] ('hnveeZUk6Rg', '%Norah Jones - Mini Concert - Happy Birthday, Willie
 Nelson! - (04-29-2020)_466.74k_[hnveeZUk6Rg]%', 1, 0)
[2024-10-24 09:47:33,123]  INFO {sqlalchemy.engine.Engine:1846} SELECT captions.rowid AS captions_rowid, captions.media_id AS captions_media_id, captions.time
 AS captions_time, captions.text AS captions_text 
FROM captions 
WHERE captions.media_id = ?
 LIMIT ? OFFSET ?
[2024-10-24 09:47:33,123]  INFO {sqlalchemy.engine.Engine:1846} [cached since 1458s ago] (2, 1, 0)
[2024-10-24 09:47:33,135]  WARN {py.warnings:110} /usr/local/calibre-web-py3/cps/editbooks.py:1568: SAWarning: Object of type <Books> not in session, add oper
ation along 'Authors.books' won't proceed (This warning originated from the Session 'autoflush' process, which was invoked automatically in response to a user
-initiated operation.)
  db_element = db_session.query(db_object).filter((func.lower(db_filter).ilike(add_element))).all()

[2024-10-24 09:47:33,141] DEBUG {cps.helper:536} Moving title: /tmp/calibre_web/01e7df17359db91c8ce152b991d8bac9 to /library/calibre-web/Norah Jones All A Dre
am/Norah Jones - Mini Concert - Happy Birthday, Willie Nelson! - (04-29-2020) (3)
[2024-10-24 09:47:33,164]  INFO {cps.services.xb_utils:169} Mapping added: <MediaBooksMapping(media_id=2, book_id=3)>
[2024-10-24 09:47:33,166]  INFO {cps.tasks.download:149} Successfully sent the requested file to http://192.168.64.43/books/meta
[2024-10-24 09:47:33,166]  INFO {sqlalchemy.engine.Engine:1846} UPDATE media SET path=?, webpath=? WHERE media.id = ?
[2024-10-24 09:47:33,166]  INFO {sqlalchemy.engine.Engine:1846} [cached since 1458s ago] ('/library/calibre-web/Norah Jones All A Dream/Norah Jones - Mini Con
cert - Happy Birthday, Willie Nelson! - (04-29-2020) (3)/Norah Jones - Mini Concert - Happy Birthda - Norah Jones All A Dream.mp4', 'https://www.youtube.com/w
atch?v=hnveeZUk6Rg&timestamp=1729777653', 2)
[2024-10-24 09:47:33,166]  INFO {sqlalchemy.engine.Engine:2707} COMMIT
[2024-10-24 09:47:33,168]  INFO {cps.tasks.download:164} Media entry updated in the database.
[2024-10-24 09:47:33,168]  INFO {cps.tasks.download:67} Download task for https://www.youtube.com/watch?v=hnveeZUk6Rg completed successfully.
[2024-10-24 09:53:32,359] DEBUG {cps.updater:331} Stable version: {'version': '0.6.24b'}

deldesir · 2024-10-28T14:29:42Z

Metadata fetch task fails after a certain period of inactivity (9:24...09:43)

[2024-10-24 09:24:07,097]  INFO {sqlalchemy.engine.Engine:1846} SELECT captions.media_id AS captions_media_id, captions.text AS captions_text, captions.time AS captions_time 
FROM captions 
WHERE captions.text LIKE ?
[2024-10-24 09:24:07,099]  INFO {sqlalchemy.engine.Engine:1846} [cached since 171.4s ago] ('%sacrifice%',)
[2024-10-24 09:43:58,529] DEBUG {cps.services.worker:91} Add Task for user: Admin - Metadata fetch task for https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:43:58,532]  INFO {cps.tasks.metadata_extract:150} Starting metadata extraction task for URL: https://www.youtube.com/watch?v=hnveeZUk6Rg
[2024-10-24 09:43:58,533] DEBUG {cps.tasks.metadata_extract:43} Executing subprocess with args: ['lb-wrapper', 'tubeadd', 'https://www.youtube.com/watch?v=hnveeZUk6Rg']
[2024-10-24 09:44:01,156]  INFO {sqlalchemy.engine.Engine:2704} ROLLBACK
[2024-10-24 09:44:01,157] ERROR {cps.tasks.metadata_extract:197} An error occurred during the metadata extraction task: A transaction is already begun on this Session.

deldesir · 2024-11-02T03:20:55Z

Should be fixed soon with next commits ensuring sessions are closed properly in every database operation. I've just tested fix candidate locally dowloading videos with 10mn+ interval.

avni · 2024-11-02T03:59:50Z

@deldesir Which commits/PRs fixes this? Can you reference them here if applicable?

deldesir · 2024-11-06T15:25:06Z

@deldesir Which commits/PRs fixes this? Can you reference them here if applicable?

List of commits that close sessions that stayed open:

PR Modeling iiab-glue.db to enable mapping of books.id (metadata.db) and media.id (xklb-metadata.db) #263:
- Ensure session can be removed from glue_db.py
PR Model xklb-metadata.db using SQLAlchemy #259:
- Add better session mgmt
PR Refactor download.py #258:
- Update download.py to close session when done
PR Refactor metadata_extract.py #257:
- Update metadata_extract.py to close session when done
PR Create xb_utils.py [to query/manipulate xklb-metadata.db (schema in xb.py) + iiab-glue.db (schema in glue-db.py)] #256:
- Update session management in xb_utils.py
PR Begin to establish 1:1 mapping between media_id (xklb-metadata.db) <-> Calibre-Web's book_id (metadata.db) #255:
- Close session after mapping
PR Refactor video_metadata to use xb #254:
- Close session after metadata retrieval

deldesir · 2024-11-12T18:28:11Z

I tested the additions on Ubuntu 24.04. I consider them as the fix for this issue. Next steps would be to merge them as part of the PRs outlined in the above message which transition to SQLAlchemy..., or to discard them in favor of the current pure SQL implementation.

@EMG70 can you confirm with a test on your side if possible?

EMG70 · 2024-11-12T19:38:53Z

I am on it now.I Will update you soon.

EMG70 · 2024-11-12T20:07:16Z

A new 24.04 VM was created and tests done without errors.
Test url https://www.youtube.com/watch?v=CAMTBzPd-WI&list=PLDqMkB5cbBA5oDg8VXM110GKc-CmvUqEZ&index=1&t=429s
SUDO IIAB-DIAGNOSTICS - https://paste.centos.org/view/bd58e216

EMG70 · 2024-11-12T20:45:28Z

A fresh size 1 IIAB was installed on a PI400 and video download tested without errors.
Test url https://www.youtube.com/watch?v=0Z4SIzgHGwk&list=PLDqMkB5cbBA5oDg8VXM110GKc-CmvUqEZ&index=2
SUDO IIAB-DIAGNOSTICS - https://paste.centos.org/view/9d54c57f

deldesir · 2024-11-13T00:35:05Z

Thanks. Please also do some search and download several videos at various intervals (13-15 mins between downloads).

EMG70 · 2024-11-13T00:43:17Z

Ok I will do.

EMG70 · 2024-11-14T19:17:47Z

More videos downloaded on 24.04 VM at different times.The search feature in Calibre-Web returned correct results as shown in screenshot.

deldesir · 2024-11-15T15:59:56Z

Thanks @EMG70. I consider this issue fixed. This ticket can be closed anytime by @holta or left open for further follow-up or feedback if necessary.

holta · 2024-11-15T16:11:33Z

Great. We can always re-open it if absolutely necessary.

avni · 2024-11-17T00:54:20Z

Thank you @deldesir, I'm trying to replicate the issue to test the patches and I can't reproduce the error (prior to applying the patches)!I tried different tabs, leaving a tab open, waiting a few minutes and coming back, and no luck. Do you know the specific steps that would reproduce the issue?

deldesir · 2024-11-17T01:21:08Z

The patches are applied in their relevant PRs and the issue is no longer reproducible, sorry.

avni · 2024-11-18T18:12:39Z

I'm a bit confused. I have an older version of IIAB that hasn't been upgraded since 10/24. It has an older version of the patches applied which originally surfaced the issue when @deldesir and I were testing live. It doesn't (I don't think) have the latest patches that fixed the session opened issue. Is there a quick way I can test if the patch to fix this issue is applied or not? A specific code change I can look for? Thanks!

deldesir · 2024-11-18T18:15:27Z

In this case, I would suggest to:

download a video
do a caption/subtitle search on the video downloaded
download another video after a while

The error should kick in and be displayed in the Tasks page, triggered by an open database session.

holta added bug Something isn't working question Further information is requested labels Oct 24, 2024

holta changed the title ~~Video download intermittently fails: A transaction is already begun on this Session.~~ Video download intermittently fails: "A transaction is already begun on this Session." Oct 24, 2024

holta changed the title ~~Video download intermittently fails: "A transaction is already begun on this Session."~~ Video download intermittently fails: "A transaction is already begun on this Session." [when testing PR #244 & 7 PRs] Oct 25, 2024

deldesir mentioned this issue Nov 11, 2024

Query captions/subtitles [e.g. video transcripts] from xklb-metadata.db #244

Open

1 task

holta closed this as completed Nov 15, 2024

deldesir self-assigned this Nov 18, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Video download intermittently fails: "A transaction is already begun on this Session." [when testing PR #244 & 7 PRs] #271

Video download intermittently fails: "A transaction is already begun on this Session." [when testing PR #244 & 7 PRs] #271

avni commented Oct 24, 2024 •

edited

Loading

holta commented Oct 24, 2024

deldesir commented Oct 24, 2024 •

edited

Loading

deldesir commented Oct 28, 2024 •

edited

Loading

deldesir commented Nov 2, 2024

avni commented Nov 2, 2024

deldesir commented Nov 6, 2024 •

edited

Loading

deldesir commented Nov 12, 2024 •

edited

Loading

EMG70 commented Nov 12, 2024

EMG70 commented Nov 12, 2024

EMG70 commented Nov 12, 2024

deldesir commented Nov 13, 2024

EMG70 commented Nov 13, 2024

EMG70 commented Nov 14, 2024

deldesir commented Nov 15, 2024

holta commented Nov 15, 2024

avni commented Nov 17, 2024

deldesir commented Nov 17, 2024

avni commented Nov 18, 2024

deldesir commented Nov 18, 2024 •

edited

Loading

Video download intermittently fails: "A transaction is already begun on this Session." [when testing PR #244 & 7 PRs] #271

Video download intermittently fails: "A transaction is already begun on this Session." [when testing PR #244 & 7 PRs] #271

Comments

avni commented Oct 24, 2024 • edited Loading

holta commented Oct 24, 2024

deldesir commented Oct 24, 2024 • edited Loading

deldesir commented Oct 28, 2024 • edited Loading

deldesir commented Nov 2, 2024

avni commented Nov 2, 2024

deldesir commented Nov 6, 2024 • edited Loading

deldesir commented Nov 12, 2024 • edited Loading

EMG70 commented Nov 12, 2024

EMG70 commented Nov 12, 2024

EMG70 commented Nov 12, 2024

deldesir commented Nov 13, 2024

EMG70 commented Nov 13, 2024

EMG70 commented Nov 14, 2024

deldesir commented Nov 15, 2024

holta commented Nov 15, 2024

avni commented Nov 17, 2024

deldesir commented Nov 17, 2024

avni commented Nov 18, 2024

deldesir commented Nov 18, 2024 • edited Loading

avni commented Oct 24, 2024 •

edited

Loading

deldesir commented Oct 24, 2024 •

edited

Loading

deldesir commented Oct 28, 2024 •

edited

Loading

deldesir commented Nov 6, 2024 •

edited

Loading

deldesir commented Nov 12, 2024 •

edited

Loading

deldesir commented Nov 18, 2024 •

edited

Loading