0s autopkgtest [01:32:24]: starting date and time: 2024-07-23 01:32:24+0000 0s autopkgtest [01:32:24]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [01:32:24]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.2jj6l0d6/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:python3-defaults,src:python3-stdlib-extensions --apt-upgrade libslow5lib --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=python3-defaults/3.12.4-1 python3-stdlib-extensions/3.12.4-2' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos03-arm64-30.secgroup --name adt-oracular-arm64-libslow5lib-20240723-013224-juju-7f2275-prod-proposed-migration-environment-2-7f0cfebe-9b92-4e94-a748-6f8cf9275ffc --image adt/ubuntu-oracular-arm64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 830s autopkgtest [01:46:14]: testbed dpkg architecture: arm64 831s autopkgtest [01:46:15]: testbed apt version: 2.9.6 831s autopkgtest [01:46:15]: @@@@@@@@@@@@@@@@@@@@ test bed setup 832s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 833s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [58.5 kB] 834s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3440 B] 834s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [407 kB] 834s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 834s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main arm64 Packages [113 kB] 834s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main arm64 c-n-f Metadata [2116 B] 834s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted arm64 Packages [43.9 kB] 834s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted arm64 c-n-f Metadata [364 B] 834s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe arm64 Packages [461 kB] 834s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe arm64 c-n-f Metadata [8752 B] 834s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse arm64 Packages [8204 B] 834s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse arm64 c-n-f Metadata [276 B] 838s Fetched 1241 kB in 2s (582 kB/s) 838s Reading package lists... 846s Reading package lists... 846s Building dependency tree... 846s Reading state information... 847s Calculating upgrade... 847s The following packages will be upgraded: 847s gcc-14-base gdisk libgcc-s1 libpython3-stdlib libstdc++6 netcat-openbsd 847s python3 python3-gdbm python3-minimal systemd-hwe-hwdb 848s 10 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 848s Need to get 1235 kB of archives. 848s After this operation, 71.7 kB of additional disk space will be used. 848s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main arm64 python3-minimal arm64 3.12.4-1 [27.1 kB] 848s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main arm64 python3 arm64 3.12.4-1 [24.0 kB] 848s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main arm64 libpython3-stdlib arm64 3.12.4-1 [9824 B] 848s Get:4 http://ftpmaster.internal/ubuntu oracular/main arm64 gcc-14-base arm64 14.1.0-5ubuntu1 [49.9 kB] 848s Get:5 http://ftpmaster.internal/ubuntu oracular/main arm64 libstdc++6 arm64 14.1.0-5ubuntu1 [749 kB] 848s Get:6 http://ftpmaster.internal/ubuntu oracular/main arm64 libgcc-s1 arm64 14.1.0-5ubuntu1 [61.8 kB] 848s Get:7 http://ftpmaster.internal/ubuntu oracular/main arm64 netcat-openbsd arm64 1.226-1.1 [43.3 kB] 848s Get:8 http://ftpmaster.internal/ubuntu oracular/main arm64 systemd-hwe-hwdb all 256.2.1 [3210 B] 848s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main arm64 python3-gdbm arm64 3.12.4-2 [18.0 kB] 848s Get:10 http://ftpmaster.internal/ubuntu oracular/main arm64 gdisk arm64 1.0.10-2 [249 kB] 853s Fetched 1235 kB in 1s (1184 kB/s) 854s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 78393 files and directories currently installed.) 854s Preparing to unpack .../python3-minimal_3.12.4-1_arm64.deb ... 854s Unpacking python3-minimal (3.12.4-1) over (3.12.3-0ubuntu1) ... 854s Setting up python3-minimal (3.12.4-1) ... 855s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 78393 files and directories currently installed.) 855s Preparing to unpack .../python3_3.12.4-1_arm64.deb ... 856s Unpacking python3 (3.12.4-1) over (3.12.3-0ubuntu1) ... 856s Preparing to unpack .../libpython3-stdlib_3.12.4-1_arm64.deb ... 856s Unpacking libpython3-stdlib:arm64 (3.12.4-1) over (3.12.3-0ubuntu1) ... 857s Preparing to unpack .../gcc-14-base_14.1.0-5ubuntu1_arm64.deb ... 857s Unpacking gcc-14-base:arm64 (14.1.0-5ubuntu1) over (14.1.0-4ubuntu2) ... 858s Setting up gcc-14-base:arm64 (14.1.0-5ubuntu1) ... 858s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 78393 files and directories currently installed.) 858s Preparing to unpack .../libstdc++6_14.1.0-5ubuntu1_arm64.deb ... 859s Unpacking libstdc++6:arm64 (14.1.0-5ubuntu1) over (14.1.0-4ubuntu2) ... 859s Setting up libstdc++6:arm64 (14.1.0-5ubuntu1) ... 859s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 78393 files and directories currently installed.) 859s Preparing to unpack .../libgcc-s1_14.1.0-5ubuntu1_arm64.deb ... 859s Unpacking libgcc-s1:arm64 (14.1.0-5ubuntu1) over (14.1.0-4ubuntu2) ... 859s Setting up libgcc-s1:arm64 (14.1.0-5ubuntu1) ... 859s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 78393 files and directories currently installed.) 859s Preparing to unpack .../netcat-openbsd_1.226-1.1_arm64.deb ... 859s Unpacking netcat-openbsd (1.226-1.1) over (1.226-1ubuntu2) ... 860s Preparing to unpack .../systemd-hwe-hwdb_256.2.1_all.deb ... 860s Unpacking systemd-hwe-hwdb (256.2.1) over (255.1.3) ... 860s Preparing to unpack .../python3-gdbm_3.12.4-2_arm64.deb ... 860s Unpacking python3-gdbm:arm64 (3.12.4-2) over (3.12.3-0ubuntu1) ... 861s Preparing to unpack .../gdisk_1.0.10-2_arm64.deb ... 861s Unpacking gdisk (1.0.10-2) over (1.0.10-1build1) ... 861s Setting up netcat-openbsd (1.226-1.1) ... 861s Setting up gdisk (1.0.10-2) ... 861s Setting up systemd-hwe-hwdb (256.2.1) ... 861s Setting up libpython3-stdlib:arm64 (3.12.4-1) ... 861s Setting up python3 (3.12.4-1) ... 863s Setting up python3-gdbm:arm64 (3.12.4-2) ... 863s Processing triggers for man-db (2.12.1-2) ... 864s Processing triggers for udev (256-1ubuntu1) ... 864s Processing triggers for libc-bin (2.39-0ubuntu9) ... 865s Reading package lists... 866s Building dependency tree... 866s Reading state information... 866s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 868s Hit:1 http://ftpmaster.internal/ubuntu oracular InRelease 868s Hit:2 http://ftpmaster.internal/ubuntu oracular-updates InRelease 868s Hit:3 http://ftpmaster.internal/ubuntu oracular-security InRelease 868s Hit:4 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 873s Reading package lists... 873s Reading package lists... 874s Building dependency tree... 874s Reading state information... 874s Calculating upgrade... 875s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 875s Reading package lists... 875s Building dependency tree... 875s Reading state information... 876s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 909s autopkgtest [01:47:33]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP PREEMPT_DYNAMIC Sat Apr 20 02:32:42 UTC 2024 910s autopkgtest [01:47:34]: @@@@@@@@@@@@@@@@@@@@ apt-source libslow5lib 922s Get:1 http://ftpmaster.internal/ubuntu oracular/universe libslow5lib 0.7.0+dfsg-2.1build1 (dsc) [2541 B] 922s Get:2 http://ftpmaster.internal/ubuntu oracular/universe libslow5lib 0.7.0+dfsg-2.1build1 (tar) [2014 kB] 922s Get:3 http://ftpmaster.internal/ubuntu oracular/universe libslow5lib 0.7.0+dfsg-2.1build1 (diff) [8280 B] 923s gpgv: Signature made Sun Mar 31 19:37:54 2024 UTC 923s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 923s gpgv: issuer "steve.langasek@ubuntu.com" 923s gpgv: Can't check signature: No public key 923s dpkg-source: warning: cannot verify inline signature for ./libslow5lib_0.7.0+dfsg-2.1build1.dsc: no acceptable signature found 925s autopkgtest [01:47:49]: testing package libslow5lib version 0.7.0+dfsg-2.1build1 926s autopkgtest [01:47:50]: build not needed 938s autopkgtest [01:48:02]: test run-pybinding-test: preparing testbed 945s Reading package lists... 945s Building dependency tree... 945s Reading state information... 946s Starting pkgProblemResolver with broken count: 0 946s Starting 2 pkgProblemResolver with broken count: 0 946s Done 946s The following additional packages will be installed: 946s libblas3 libgfortran5 liblapack3 libslow5-0t64 libslow5-dev libstreamvbyte0 946s python3-all python3-numpy python3-slow5 946s Suggested packages: 946s gcc gfortran python-numpy-doc python3-dev python3-pytest 946s The following NEW packages will be installed: 946s autopkgtest-satdep libblas3 libgfortran5 liblapack3 libslow5-0t64 946s libslow5-dev libstreamvbyte0 python3-all python3-numpy python3-slow5 947s 0 upgraded, 10 newly installed, 0 to remove and 0 not upgraded. 947s Need to get 6999 kB/7000 kB of archives. 947s After this operation, 35.4 MB of additional disk space will be used. 947s Get:1 /tmp/autopkgtest.BmBxSK/1-autopkgtest-satdep.deb autopkgtest-satdep arm64 0 [728 B] 947s Get:2 http://ftpmaster.internal/ubuntu oracular/main arm64 libblas3 arm64 3.12.0-3build1 [143 kB] 947s Get:3 http://ftpmaster.internal/ubuntu oracular/main arm64 libgfortran5 arm64 14.1.0-5ubuntu1 [438 kB] 947s Get:4 http://ftpmaster.internal/ubuntu oracular/main arm64 liblapack3 arm64 3.12.0-3build1 [2241 kB] 947s Get:5 http://ftpmaster.internal/ubuntu oracular/universe arm64 libslow5-0t64 arm64 0.7.0+dfsg-2.1build1 [61.9 kB] 947s Get:6 http://ftpmaster.internal/ubuntu oracular/universe arm64 libslow5-dev arm64 0.7.0+dfsg-2.1build1 [90.3 kB] 947s Get:7 http://ftpmaster.internal/ubuntu oracular/universe arm64 libstreamvbyte0 arm64 0.4.1-4ubuntu1 [6260 B] 947s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main arm64 python3-all arm64 3.12.4-1 [882 B] 947s Get:9 http://ftpmaster.internal/ubuntu oracular/main arm64 python3-numpy arm64 1:1.26.4+ds-10 [3565 kB] 947s Get:10 http://ftpmaster.internal/ubuntu oracular/universe arm64 python3-slow5 arm64 0.7.0+dfsg-2.1build1 [452 kB] 950s Fetched 6999 kB in 1s (7013 kB/s) 951s Selecting previously unselected package libblas3:arm64. 951s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 78396 files and directories currently installed.) 951s Preparing to unpack .../0-libblas3_3.12.0-3build1_arm64.deb ... 951s Unpacking libblas3:arm64 (3.12.0-3build1) ... 951s Selecting previously unselected package libgfortran5:arm64. 952s Preparing to unpack .../1-libgfortran5_14.1.0-5ubuntu1_arm64.deb ... 952s Unpacking libgfortran5:arm64 (14.1.0-5ubuntu1) ... 952s Selecting previously unselected package liblapack3:arm64. 953s Preparing to unpack .../2-liblapack3_3.12.0-3build1_arm64.deb ... 953s Unpacking liblapack3:arm64 (3.12.0-3build1) ... 954s Selecting previously unselected package libslow5-0t64:arm64. 955s Preparing to unpack .../3-libslow5-0t64_0.7.0+dfsg-2.1build1_arm64.deb ... 955s Unpacking libslow5-0t64:arm64 (0.7.0+dfsg-2.1build1) ... 955s Selecting previously unselected package libslow5-dev:arm64. 956s Preparing to unpack .../4-libslow5-dev_0.7.0+dfsg-2.1build1_arm64.deb ... 956s Unpacking libslow5-dev:arm64 (0.7.0+dfsg-2.1build1) ... 956s Selecting previously unselected package libstreamvbyte0:arm64. 957s Preparing to unpack .../5-libstreamvbyte0_0.4.1-4ubuntu1_arm64.deb ... 957s Unpacking libstreamvbyte0:arm64 (0.4.1-4ubuntu1) ... 957s Selecting previously unselected package python3-all. 958s Preparing to unpack .../6-python3-all_3.12.4-1_arm64.deb ... 958s Unpacking python3-all (3.12.4-1) ... 958s Selecting previously unselected package python3-numpy. 958s Preparing to unpack .../7-python3-numpy_1%3a1.26.4+ds-10_arm64.deb ... 958s Unpacking python3-numpy (1:1.26.4+ds-10) ... 959s Selecting previously unselected package python3-slow5. 959s Preparing to unpack .../8-python3-slow5_0.7.0+dfsg-2.1build1_arm64.deb ... 959s Unpacking python3-slow5 (0.7.0+dfsg-2.1build1) ... 960s Selecting previously unselected package autopkgtest-satdep. 960s Preparing to unpack .../9-1-autopkgtest-satdep.deb ... 960s Unpacking autopkgtest-satdep (0) ... 961s Setting up libstreamvbyte0:arm64 (0.4.1-4ubuntu1) ... 961s Setting up python3-all (3.12.4-1) ... 961s Setting up libblas3:arm64 (3.12.0-3build1) ... 961s update-alternatives: using /usr/lib/aarch64-linux-gnu/blas/libblas.so.3 to provide /usr/lib/aarch64-linux-gnu/libblas.so.3 (libblas.so.3-aarch64-linux-gnu) in auto mode 961s Setting up libslow5-0t64:arm64 (0.7.0+dfsg-2.1build1) ... 961s Setting up libgfortran5:arm64 (14.1.0-5ubuntu1) ... 961s Setting up liblapack3:arm64 (3.12.0-3build1) ... 961s update-alternatives: using /usr/lib/aarch64-linux-gnu/lapack/liblapack.so.3 to provide /usr/lib/aarch64-linux-gnu/liblapack.so.3 (liblapack.so.3-aarch64-linux-gnu) in auto mode 961s Setting up libslow5-dev:arm64 (0.7.0+dfsg-2.1build1) ... 961s Setting up python3-numpy (1:1.26.4+ds-10) ... 965s Setting up python3-slow5 (0.7.0+dfsg-2.1build1) ... 965s Setting up autopkgtest-satdep (0) ... 965s Processing triggers for man-db (2.12.1-2) ... 965s Processing triggers for libc-bin (2.39-0ubuntu9) ... 979s (Reading database ... 79333 files and directories currently installed.) 979s Removing autopkgtest-satdep (0) ... 982s autopkgtest [01:48:46]: test run-pybinding-test: [----------------------- 984s Testing with python3.12 in /tmp/autopkgtest.BmBxSK/autopkgtest_tmp: 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: examples/example.slow5, mode: r 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: b'examples/example.slow5', mode: b'r' 986s 23-Jul-24 01:48:50 - [DEBUG]: Number of read_groups: 1 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: examples/example.slow5, mode: r 986s 23-Jul-24 01:48:50 - [DEBUG]: Creating/loading index... 986s [slow5_idx_init::INFO] Index file not found. Creating an index at 'examples/example.slow5.idx'. 986s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_names starting 986s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_names aux_len: 0 986s 23-Jul-24 01:48:50 - [WARNING]: get_aux_names ret is NULL 986s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_types starting 986s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_types aux_len: 0 986s 23-Jul-24 01:48:50 - [WARNING]: get_aux_types self.s5_aux_type is NULL 986s 23-Jul-24 01:48:50 - [WARNING]: get_read unknown aux name: read_number 986s 23-Jul-24 01:48:50 - [WARNING]: get_read unknown aux name: blah 986s 23-Jul-24 01:48:50 - [WARNING]: get_read unknown aux name: start_mux 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: -1 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 986s [slow5_idx_get::ERROR] Read ID 'null_read' was not found. At src/slow5_idx.c:441 986s 23-Jul-24 01:48:50 - [DEBUG]: get_read return not 0: -7 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_hdr_keys head_len: 32 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_hdr_keys head_len: 32 986s 23-Jul-24 01:48:50 - [DEBUG]: examples/example.slow5 closed 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: examples/example2.slow5, mode: r 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 986s 23-Jul-24 01:48:50 - [DEBUG]: Number of read_groups: 4 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: examples/example2.slow5, mode: r 986s 23-Jul-24 01:48:50 - [DEBUG]: Creating/loading index... 986s [slow5_idx_init::INFO] Index file not found. Creating an index at 'examples/example2.slow5.idx'. 986s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_names starting 986s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_names aux_len: 5 986s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_types starting 986s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_types aux_len: 5 986s 23-Jul-24 01:48:50 - [WARNING]: get_read unknown aux name: blah 986s 23-Jul-24 01:48:50 - [WARNING]: get_read unknown aux name: blah 986s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_names starting 986s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_names aux_len: 5 986s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_types starting 986s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_types aux_len: 5 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: -1 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 986s 23-Jul-24 01:48:50 - [DEBUG]: examples/example2.slow5 closed 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: examples/example_write.slow5, mode: w 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: b'examples/example_write.slow5', mode: b'w' 986s 23-Jul-24 01:48:50 - [DEBUG]: Not writing blow5, skipping compression steps 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: examples/example2.slow5, mode: r 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 986s 23-Jul-24 01:48:50 - [DEBUG]: Number of read_groups: 4 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: checking header stuff... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: writting header... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: header written 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 305872 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 152707 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 305872 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 152707 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 305872 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 152707 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 305906 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 152741 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: -1 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 986s 23-Jul-24 01:48:50 - [DEBUG]: examples/example_write.slow5 closed 986s 23-Jul-24 01:48:50 - [DEBUG]: examples/example2.slow5 closed 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: examples/example_write_append.blow5, mode: w 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: b'examples/example_write_append.blow5', mode: b'w' 986s 23-Jul-24 01:48:50 - [DEBUG]: examples/example_write.slow5 already closed 986s 23-Jul-24 01:48:50 - [DEBUG]: pathname: examples/example_write.slow5 986s 23-Jul-24 01:48:50 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 986s 23-Jul-24 01:48:50 - [DEBUG]: total_time_yield_reads: 0.0 seconds 986s 23-Jul-24 01:48:50 - [DEBUG]: total_single_write_time: 0.02643108367919922 seconds 986s 23-Jul-24 01:48:50 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 986s 23-Jul-24 01:48:50 - [DEBUG]: total_multi_write_time: 0.0 seconds 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: examples/example2.slow5, mode: r 986s 23-Jul-24 01:48:50 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 986s 23-Jul-24 01:48:50 - [DEBUG]: Number of read_groups: 4 986s 23-Jul-24 01:48:50 - [DEBUG]: pathname: examples/example2.slow5 986s 23-Jul-24 01:48:50 - [DEBUG]: total_time_slow5_get_next: 0.016489028930664062 seconds 986s 23-Jul-24 01:48:50 - [DEBUG]: total_time_yield_reads: 0.017148494720458984 seconds 986s 23-Jul-24 01:48:50 - [DEBUG]: total_single_write_time: 0.0 seconds 986s 23-Jul-24 01:48:50 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 986s 23-Jul-24 01:48:50 - [DEBUG]: total_multi_write_time: 0.0 seconds 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: checking header stuff... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: writting header... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: header written 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 152976 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 76384 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 152976 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 76384 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 152976 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 76384 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 153010 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 986s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 986s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 76418 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: -1 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 987s 23-Jul-24 01:48:50 - [DEBUG]: examples/example2.slow5 closed 987s 23-Jul-24 01:48:50 - [DEBUG]: examples/example_write_append.blow5 closed 987s 23-Jul-24 01:48:50 - [DEBUG]: FILE: examples/example_write_append.blow5, mode: a 987s 23-Jul-24 01:48:50 - [DEBUG]: FILE: b'examples/example_write_append.blow5', mode: b'a' 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_hdr_keys head_len: 38 987s |==============================================| 987s | pyslow5 test launch | 987s |==============================================| 987s ['__class__', '__delattr__', '__dir__', '__doc__', '__eq__', '__format__', '__ge__', '__getattribute__', '__getstate__', '__gt__', '__hash__', '__init__', '__init_subclass__', '__le__', '__lt__', '__ne__', '__new__', '__reduce__', '__reduce_ex__', '__repr__', '__setattr__', '__setstate__', '__sizeof__', '__str__', '__subclasshook__', '_aux_header_type_validation', '_convert_to_pA', '_get_batches', '_get_read', '_get_read_aux', '_get_read_multi', '_get_seq_read_aux', '_header_type_validation', '_multi_record_type_validation', '_record_type_validation', 'close', 'get_all_headers', 'get_aux_names', 'get_aux_types', 'get_empty_header', 'get_empty_record', 'get_header_names', 'get_header_value', 'get_read', 'get_read_ids', 'get_read_list', 'get_read_list_multi', 'seq_reads', 'seq_reads_multi', 'write_header', 'write_record', 'write_record_batch'] 987s slow5 file opened and object created in: 0.0212 seconds 987s ============================================== 987s get_read check, r1 987s get_read in: 0.1163 seconds 987s read_id: r1 987s read_group: 0 987s digitisation: 8192.0 987s offset: 23.0 987s range: 1467.61 987s sampling_rate: 4000.0 987s len_raw_signal: 59676 987s signal: [1039 588 588 593 586 574 570 585 588 586] 987s pylen of signal: 59676 987s AUX FIELDS: 987s read_number: None 987s start_mux: None 987s blah: None 987s ============================================== 987s get_read check, r4, converte to pA 987s get_read in: 0.0491 seconds 987s read_id: r4 987s read_group: 0 987s digitisation: 8192.0 987s offset: 23.0 987s range: 1467.61 987s sampling_rate: 4000.0 987s len_raw_signal: 59670 987s signal: [190.25902 108.92418 109.46163 109.10333 107.67012 108.38673 987s 108.745026 109.10333 111.074 108.38673 ] 987s pylen of signal: 59670 987s signal value type: 987s ============================================== 987s seq_reads check, all reads 987s seq_reads readIDs: 987s type check reads: 987s r1 987s r2 987s r3 987s r4 987s r5 987s seq_reads in: 0.0116 seconds 987s ============================================== 987s Yield check, selected reads 987s get_read_list in: 0.0 seconds 987s yielded readIDs: 987s r1 r1 987s r3 r3 987s null_read read not found, None returned 987s r5 r5 987s r2 r2 987s r1 r1 987s ============================================== 987s Get headder names 987s header names: 987s ['asic_id', 'asic_id_eeprom', 'asic_temp', 'auto_update', 'auto_update_source', 'bream_core_version', 'bream_is_standard', 'bream_map_version', 'bream_ont_version', 'bream_prod_version', 'bream_rnd_version', 'device_id', 'exp_script_name', 'exp_script_purpose', 'exp_start_time', 'experiment_kit', 'experiment_type', 'file_version', 'filename', 'flow_cell_id', 'heatsink_temp', 'hostname', 'installation_type', 'local_firmware_file', 'operating_system', 'protocol_run_id', 'protocols_version', 'run_id', 'sample_frequency', 'usb_config', 'user_filename_input', 'version'] 987s ============================================== 987s get_all_headers 987s {'asic_id': '3574887596', 'asic_id_eeprom': '0', 'asic_temp': '29.2145729', 'auto_update': '1', 'auto_update_source': 'https://mirror.oxfordnanoportal.com/software/MinKNOW/', 'bream_core_version': '1.1.20.1', 'bream_is_standard': '1', 'bream_map_version': '1.1.20.1', 'bream_ont_version': '1.1.20.1', 'bream_prod_version': '1.1.20.1', 'bream_rnd_version': '0.1.1', 'device_id': 'MN16450', 'exp_script_name': 'python/recipes/nc/NC_48Hr_Sequencing_Run_FLO-MIN106_SQK-LSK108.py', 'exp_script_purpose': 'sequencing_run', 'exp_start_time': '1479433093', 'experiment_kit': 'genomic_dna', 'experiment_type': 'customer_qc', 'file_version': '1', 'filename': 'deamernanopore_20161117_fnfab43577_mn16450_sequencing_run_ma_821_r9_4_na12878_11_17_16_88738', 'flow_cell_id': 'FAB43577', 'heatsink_temp': '33.9921875', 'hostname': 'DEAMERNANOPORE', 'installation_type': 'map', 'local_firmware_file': '0', 'operating_system': 'Windows 6.2', 'protocol_run_id': 'a4429838-103c-497f-a824-7dffa72cfd81', 'protocols_version': '1.1.20', 'run_id': 'd6e473a6d513ec6bfc150c60fd4556d72f0e6d18', 'sample_frequency': '4000', 'usb_config': '1.0.11_ONT#MinION_fpga_1.0.1#ctrl#Auto', 'user_filename_input': 'ma_821_r9.4_na12878_11_17_16', 'version': '1.1.20'} 987s ============================================== 987s Get headder attributes 987s flow_cell_id: FAB43577 987s exp_start_time: 1479433093 987s heatsink_temp: 33.9921875 987s asic_id: 3574887596 987s asic_id_eeprom: 0 987s asic_temp: 29.2145729 987s auto_update: 1 987s auto_update_source: https://mirror.oxfordnanoportal.com/software/MinKNOW/ 987s bream_core_version: 1.1.20.1 987s bream_is_standard: 1 987s bream_map_version: 1.1.20.1 987s bream_ont_version: 1.1.20.1 987s bream_prod_version: 1.1.20.1 987s bream_rnd_version: 0.1.1 987s device_id: MN16450 987s exp_script_name: python/recipes/nc/NC_48Hr_Sequencing_Run_FLO-MIN106_SQK-LSK108.py 987s exp_script_purpose: sequencing_run 987s exp_start_time: 1479433093 987s experiment_kit: genomic_dna 987s experiment_type: customer_qc 987s file_version: 1 987s filename: deamernanopore_20161117_fnfab43577_mn16450_sequencing_run_ma_821_r9_4_na12878_11_17_16_88738 987s flow_cell_id: FAB43577 987s heatsink_temp: 33.9921875 987s hostname: DEAMERNANOPORE 987s installation_type: map 987s local_firmware_file: 0 987s operating_system: Windows 6.2 987s protocol_run_id: a4429838-103c-497f-a824-7dffa72cfd81 987s protocols_version: 1.1.20 987s run_id: d6e473a6d513ec6bfc150c60fd4556d72f0e6d18 987s sample_frequency: 4000 987s usb_config: 1.0.11_ONT#MinION_fpga_1.0.1#ctrl#Auto 987s user_filename_input: ma_821_r9.4_na12878_11_17_16 987s version: 1.1.20 987s ============================================== 987s get_read check, 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 987s read_id: 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 987s read_group: 3 987s digitisation: 8192.0 987s offset: 6.0 987s range: 1444.86 987s sampling_rate: 4000.0 987s len_raw_signal: 38164 987s signal: [1462 1075 795 801 797 788 817 791 801 802] 987s pylen of signal: 38164 987s AUX FIELDS: 987s read_number: 2287 987s start_mux: 2 987s blah: None 987s AUX FIELDS: 987s blah: None 987s AUX FIELDS: 987s read_number: 2287 987s ============================================== 987s Get aux names 987s aux names: 987s ['channel_number', 'median_before', 'read_number', 'start_mux', 'start_time'] 987s ============================================== 987s Get aux types 987s aux types: 987s [22, 9, 2, 4, 7] 987s ============================================== 987s AUX FIELDS: 987s channel_number: 391 987s median_before: 260.557264 987s read_number: 2287 987s start_mux: 2 987s start_time: 36886851 987s ============================================== 987s seq_reads with aux: 987s type check reads: 987s r0 987s read_number 4019 987s r1 987s read_number 2287 987s r2 987s read_number 4019 987s r3 987s read_number 2287 987s r4 987s read_number 4019 987s r5 987s read_number 2287 987s 0a238451-b9ed-446d-a152-badd074006c4 987s read_number 4019 987s 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 987s read_number 2287 987s ============================================== 987s write reads no aux 987s ret: write_header(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ============================================== 987s append reads no aux 987s ret: write_header(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s get_all_headers 987s 23-Jul-24 01:48:50 - [DEBUG]: FILE: examples/example2.slow5, mode: r 987s 23-Jul-24 01:48:50 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 987s 23-Jul-24 01:48:50 - [DEBUG]: Number of read_groups: 4 987s 23-Jul-24 01:48:50 - [DEBUG]: pathname: examples/example2.slow5 987s 23-Jul-24 01:48:50 - [DEBUG]: total_time_slow5_get_next: 0.016455650329589844 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: total_time_yield_reads: 0.01713418960571289 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: total_single_write_time: 0.0 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 152983 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 76391 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 152983 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 76391 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 152983 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 76391 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 153017 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 76425 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: -1 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 987s 23-Jul-24 01:48:50 - [DEBUG]: examples/example2.slow5 closed 987s 23-Jul-24 01:48:50 - [DEBUG]: examples/example_write_append.blow5 closed 987s 23-Jul-24 01:48:50 - [DEBUG]: FILE: examples/example_write_aux.blow5, mode: w 987s 23-Jul-24 01:48:50 - [DEBUG]: FILE: b'examples/example_write_aux.blow5', mode: b'w' 987s 23-Jul-24 01:48:50 - [DEBUG]: examples/example_write_append.blow5 already closed 987s 23-Jul-24 01:48:50 - [DEBUG]: pathname: examples/example_write_append.blow5 987s 23-Jul-24 01:48:50 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: total_time_yield_reads: 0.0 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: total_single_write_time: 0.026410341262817383 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: FILE: examples/example2.slow5, mode: r 987s 23-Jul-24 01:48:50 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 987s 23-Jul-24 01:48:50 - [DEBUG]: Number of read_groups: 4 987s 23-Jul-24 01:48:50 - [DEBUG]: pathname: examples/example2.slow5 987s 23-Jul-24 01:48:50 - [DEBUG]: total_time_slow5_get_next: 0.016641616821289062 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: total_time_yield_reads: 0.017289400100708008 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: total_single_write_time: 0.0 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_names starting 987s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_names aux_len: 5 987s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_types starting 987s 23-Jul-24 01:48:50 - [DEBUG]: get_aux_types aux_len: 5 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: checking header stuff... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: writting header... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: header written 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 67258 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:50 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:50 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_write() ret: 32408 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:50 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 67258 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 32408 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 67260 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 32408 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 67298 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 32446 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: -1 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example2.slow5 closed 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example_write_aux.blow5 closed 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: examples/example_write_append_aux.blow5, mode: w 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: b'examples/example_write_append_aux.blow5', mode: b'w' 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example_write_aux.blow5 already closed 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example_write_aux.blow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.026555776596069336 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: examples/example2.slow5, mode: r 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 987s 23-Jul-24 01:48:51 - [DEBUG]: Number of read_groups: 4 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example2.slow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.016705989837646484 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.01767873764038086 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_names starting 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_names aux_len: 5 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_types starting 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_types aux_len: 5 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checking header stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: writting header... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: header written 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 153008 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 76416 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 153008 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 76416 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 153008 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 76416 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 153042 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 76450 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: -1 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example2.slow5 closed 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example_write_append_aux.blow5 closed 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: examples/example_write_append_aux.blow5, mode: a 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: b'examples/example_write_append_aux.blow5', mode: b'a' 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example_write_append.blow5 already closed 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example_write_append.blow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.026385784149169922 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: examples/example2.slow5, mode: r 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 987s 23-Jul-24 01:48:51 - [DEBUG]: Number of read_groups: 4 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example2.slow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.01653599739074707 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.017388343811035156 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_names starting 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_names aux_len: 5 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_types starting 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_types aux_len: 5 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 153015 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 76423 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 153015 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 76423 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 153015 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 76423 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 153049 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_write() ret: 76457 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: slow5_rec_free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: -1 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example2.slow5 closed 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example_write_append_aux.blow5 closed 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: examples/example2.slow5, mode: r 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 987s 23-Jul-24 01:48:51 - [DEBUG]: Number of read_groups: 4 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next_multi return: 3 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_names starting 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_names aux_len: 5 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_types starting 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_types aux_len: 5 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next_multi return: 3 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next_multi return: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next_multi has no more batches - batchsize:3 ret:2 987s 23-Jul-24 01:48:51 - [DEBUG]: seq_reads_multi timings: 987s 23-Jul-24 01:48:51 - [DEBUG]: aux_total_time: 0.0001914501190185547 987s 23-Jul-24 01:48:51 - [DEBUG]: primary_total_time: 0.0001590251922607422 987s 23-Jul-24 01:48:51 - [DEBUG]: pA_total_time: 0.0012509822845458984 987s 23-Jul-24 01:48:51 - [DEBUG]: signal_total_time: 0.00014543533325195312 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example2.slow5 closed 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: examples/example2.slow5, mode: r 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 987s 23-Jul-24 01:48:51 - [DEBUG]: Number of read_groups: 4 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example2.slow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.012245416641235352 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.001623392105102539 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: examples/example2.slow5, mode: r 987s 23-Jul-24 01:48:51 - [DEBUG]: Creating/loading index... 987s 23-Jul-24 01:48:51 - [DEBUG]: Setting up batching... 987s 23-Jul-24 01:48:51 - [DEBUG]: read_list: ['r0', 'r1', 'r2', 'r3', 'r4', 'r5', '0a238451-b9ed-446d-a152-badd074006c4', '0d624d4b-671f-40b8-9798-84f2ccc4d7fc'] 987s 23-Jul-24 01:48:51 - [DEBUG]: batch for loop start 987s 23-Jul-24 01:48:51 - [DEBUG]: Batch: r0,r1,r2 987s 23-Jul-24 01:48:51 - [DEBUG]: Starting rid assignment 987s 23-Jul-24 01:48:51 - [DEBUG]: readID: r0, bin: b'r0' 987s 23-Jul-24 01:48:51 - [DEBUG]: readID: r1, bin: b'r1' 987s 23-Jul-24 01:48:51 - [DEBUG]: readID: r2, bin: b'r2' 987s 23-Jul-24 01:48:51 - [DEBUG]: rid assignment complete 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_batch: num_reads: 3 987s 23-Jul-24 01:48:51 - [DEBUG]: get_read_multi slow5_get_batch ret: 3 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_names starting 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_names aux_len: 5 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_types starting 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_types aux_len: 5 987s 23-Jul-24 01:48:51 - [DEBUG]: Batch: r3,r4,r5 987s 23-Jul-24 01:48:51 - [DEBUG]: Starting rid assignment 987s 23-Jul-24 01:48:51 - [DEBUG]: readID: r3, bin: b'r3' 987s 23-Jul-24 01:48:51 - [DEBUG]: readID: r4, bin: b'r4' 987s 23-Jul-24 01:48:51 - [DEBUG]: readID: r5, bin: b'r5' 987s 23-Jul-24 01:48:51 - [DEBUG]: rid assignment complete 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_batch: num_reads: 3 987s 23-Jul-24 01:48:51 - [DEBUG]: get_read_multi slow5_get_batch ret: 3 987s 23-Jul-24 01:48:51 - [DEBUG]: Batch: 0a238451-b9ed-446d-a152-badd074006c4,0d624d4b-671f-40b8-9798-84f2ccc4d7fc 987s 23-Jul-24 01:48:51 - [DEBUG]: Starting rid assignment 987s 23-Jul-24 01:48:51 - [DEBUG]: readID: 0a238451-b9ed-446d-a152-badd074006c4, bin: b'0a238451-b9ed-446d-a152-badd074006c4' 987s 23-Jul-24 01:48:51 - [DEBUG]: readID: 0d624d4b-671f-40b8-9798-84f2ccc4d7fc, bin: b'0d624d4b-671f-40b8-9798-84f2ccc4d7fc' 987s 23-Jul-24 01:48:51 - [DEBUG]: rid assignment complete 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_batch: num_reads: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: get_read_multi slow5_get_batch ret: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: seq_reads_multi timings: 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example2.slow5 closed 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: examples/example_write_aux_multi.slow5, mode: w 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: b'examples/example_write_aux_multi.slow5', mode: b'w' 987s 23-Jul-24 01:48:51 - [DEBUG]: Not writing blow5, skipping compression steps 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example_write_append_aux.blow5 already closed 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example_write_append_aux.blow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.02674579620361328 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: examples/example2.slow5, mode: r 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 987s 23-Jul-24 01:48:51 - [DEBUG]: Number of read_groups: 4 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example2.slow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.016518831253051758 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.017438650131225586 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_names starting 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_names aux_len: 5 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_types starting 987s 23-Jul-24 01:48:51 - [DEBUG]: get_aux_types aux_len: 5 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: 0 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next return: -1 987s 23-Jul-24 01:48:51 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: Setting up batching... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: batch for loop start 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checking header stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: writting header... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: header written 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_write_batch() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: free() aux 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_write_batch() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: free() aux 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: _record_type_validation running 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: doing aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux passed tests... 987s 23-Jul-24 01:48:51 - [DEBUG]: _record_type_validation: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: _record_type_validation done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_rec_init() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write assignments done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write processing raw_signal 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: self.write raw_signal done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: aux stuff done 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: slow5_write_batch() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: free() 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: free() aux 987s 23-Jul-24 01:48:51 - [DEBUG]: write_record_batch: function complete, returning 0 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example2.slow5 closed 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example_write_aux_multi.slow5 closed 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: examples/example2.slow5, mode: r 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 987s 23-Jul-24 01:48:51 - [DEBUG]: Number of read_groups: 4 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example2.slow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.01657414436340332 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.017510652542114258 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: FILE: examples/example2.slow5, mode: r 987s 23-Jul-24 01:48:51 - [DEBUG]: Creating/loading index... 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example2.slow5 closed 987s {'asic_id': 'test_0', 'asic_id_eeprom': 'test_1', 'asic_temp': 'test_2', 'asic_version': 'test_3', 'auto_update': 'test_4', 'auto_update_source': 'test_5', 'barcoding_enabled': 'test_6', 'bream_is_standard': 'test_7', 'configuration_version': 'test_8', 'device_id': 'test_9', 'device_type': 'test_10', 'distribution_status': 'test_11', 'distribution_version': 'test_12', 'exp_script_name': 'test_13', 'exp_script_purpose': 'test_14', 'exp_start_time': 'test_15', 'experiment_duration_set': 'test_16', 'flow_cell_id': 'test_17', 'flow_cell_product_code': 'test_18', 'guppy_version': 'test_19', 'heatsink_temp': 'test_20', 'hostname': 'test_21', 'hublett_board_id': 'test_36', 'installation_type': 'test_22', 'local_basecalling': 'test_23', 'operating_system': 'test_24', 'package': 'test_25', 'protocol_group_id': 'test_26', 'protocol_run_id': 'test_27', 'protocol_start_time': 'test_28', 'protocols_version': 'test_29', 'run_id': 'test_30', 'sample_frequency': 'test_31', 'sample_id': 'test_32', 'satellite_firmware_version': 'test_37', 'sequencing_kit': 'test_33', 'usb_config': 'test_34', 'version': 'test_35'} 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ============================================== 987s write reads with aux 987s ret: write_header(): 0 987s ret: write_header(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ============================================== 987s append reads with aux 987s ret: write_header(): 0 987s ret: write_header(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ret: write_record(): 0 987s ============================================== 987s seq_reads_multi with aux: 987s type check reads: 987s r0 987s read_number 4019 987s r1 987s read_number 2287 987s r2 987s read_number 4019 987s r3 987s read_number 2287 987s r4 987s read_number 4019 987s r5 987s read_number 2287 987s 0a238451-b9ed-446d-a152-badd074006c4 987s read_number 4019 987s 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 987s read_number 2287 987s ============================================== 987s get_reads_multi with aux: 987s type check reads: 987s r0 987s read_number 4019 987s r1 987s read_number 2287 987s r2 987s read_number 4019 987s r3 987s read_number 2287 987s r4 987s read_number 4019 987s r5 987s read_number 2287 987s 0a238451-b9ed-446d-a152-badd074006c4 987s read_number 4019 987s 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 987s read_number 2287 987s ============================================== 987s write reads with aux multi 987s ret: write_header(): 0 987s ret: write_header(): 0 987s {'r0': {'read_id': 'r0', 'read_group': 0, 'digitisation': 8192.0, 'offset': 2.0, 'range': 1444.86, 'sampling_rate': 4000.0, 'len_raw_signal': 76460, 'signal': array([1299, 771, 556, ..., 554, 560, 566], dtype=int16)}, 'r1': {'read_id': 'r1', 'read_group': 0, 'digitisation': 8192.0, 'offset': 6.0, 'range': 1444.86, 'sampling_rate': 4000.0, 'len_raw_signal': 38164, 'signal': array([1462, 1075, 795, ..., 696, 706, 702], dtype=int16)}, 'r2': {'read_id': 'r2', 'read_group': 1, 'digitisation': 8192.0, 'offset': 2.0, 'range': 1444.86, 'sampling_rate': 4000.0, 'len_raw_signal': 76460, 'signal': array([1299, 771, 556, ..., 554, 560, 566], dtype=int16)}, 'r3': {'read_id': 'r3', 'read_group': 1, 'digitisation': 8192.0, 'offset': 6.0, 'range': 1444.86, 'sampling_rate': 4000.0, 'len_raw_signal': 38164, 'signal': array([1462, 1075, 795, ..., 696, 706, 702], dtype=int16)}, 'r4': {'read_id': 'r4', 'read_group': 2, 'digitisation': 8192.0, 'offset': 2.0, 'range': 1444.86, 'sampling_rate': 4000.0, 'len_raw_signal': 76460, 'signal': array([1299, 771, 556, ..., 554, 560, 566], dtype=int16)}, 'r5': {'read_id': 'r5', 'read_group': 2, 'digitisation': 8192.0, 'offset': 6.0, 'range': 1444.86, 'sampling_rate': 4000.0, 'len_raw_signal': 38164, 'signal': array([1462, 1075, 795, ..., 696, 706, 702], dtype=int16)}, '0a238451-b9ed-446d-a152-badd074006c4': {'read_id': '0a238451-b9ed-446d-a152-badd074006c4', 'read_group': 3, 'digitisation': 8192.0, 'offset': 2.0, 'range': 1444.86, 'sampling_rate': 4000.0, 'len_raw_signal': 76460, 'signal': array([1299, 771, 556, ..., 554, 560, 566], dtype=int16)}, '0d624d4b-671f-40b8-9798-84f2ccc4d7fc': {'read_id': '0d624d4b-671f-40b8-9798-84f2ccc4d7fc', 'read_group': 3, 'digitisation': 8192.0, 'offset': 6.0, 'range': 1444.86, 'sampling_rate': 4000.0, 'len_raw_signal': 38164, 'signal': array([1462, 1075, 795, ..., 696, 706, 702], dtype=int16)}} 987s {'r0': {'channel_number': '281', 'median_before': 231.363533, 'read_number': 4019, 'start_mux': 1, 'start_time': 78470500}, 'r1': {'channel_number': '391', 'median_before': 260.557264, 'read_number': 2287, 'start_mux': 2, 'start_time': 36886851}, 'r2': {'channel_number': '281', 'median_before': 231.363533, 'read_number': 4019, 'start_mux': 1, 'start_time': 78470500}, 'r3': {'channel_number': '391', 'median_before': 260.557264, 'read_number': 2287, 'start_mux': 2, 'start_time': 36886851}, 'r4': {'channel_number': '281', 'median_before': 231.363533, 'read_number': 4019, 'start_mux': 1, 'start_time': 78470500}, 'r5': {'channel_number': '391', 'median_before': 260.557264, 'read_number': 2287, 'start_mux': 2, 'start_time': 36886851}, '0a238451-b9ed-446d-a152-badd074006c4': {'channel_number': '281', 'median_before': 231.363533, 'read_number': 4019, 'start_mux': 1, 'start_time': 78470500}, '0d624d4b-671f-40b8-9798-84f2ccc4d7fc': {'channel_number': '391', 'median_before': 260.557264, 'read_number': 2287, 'start_mux': 2, 'start_time': 36886851}} 987s ret: write_record(): 0 987s ============================================== 987s get all readIDs from index 987s ['r0', 'r1', 'r2', 'r3', 'r4', 'r5', '0a238451-b9ed-446d-a152-badd074006c4', '0d624d4b-671f-40b8-9798-84f2ccc4d7fc'] 987s number of reads: 8 987s ============================================== 987s done 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example.slow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.011050224304199219 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.011502265930175781 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example2.slow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.016616344451904297 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.030620813369750977 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example_write_aux_multi.slow5 already closed 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example_write_aux_multi.slow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.028905630111694336 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.05755281448364258 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example2.slow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: examples/example_write_append_aux.blow5 already closed 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example_write_append_aux.blow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.026465177536010742 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: pathname: examples/example2.slow5 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_time_yield_reads: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_single_write_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 987s 23-Jul-24 01:48:51 - [DEBUG]: total_multi_write_time: 0.0 seconds 989s autopkgtest [01:48:53]: test run-pybinding-test: -----------------------] 992s autopkgtest [01:48:56]: test run-pybinding-test: - - - - - - - - - - results - - - - - - - - - - 992s run-pybinding-test PASS 994s autopkgtest [01:48:58]: test run-pkg-test: preparing testbed 1669s autopkgtest [02:00:13]: testbed dpkg architecture: arm64 1671s autopkgtest [02:00:15]: testbed apt version: 2.9.6 1671s autopkgtest [02:00:15]: @@@@@@@@@@@@@@@@@@@@ test bed setup 1674s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 1677s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 1678s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [58.5 kB] 1678s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3440 B] 1678s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [407 kB] 1678s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main arm64 Packages [113 kB] 1678s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main arm64 c-n-f Metadata [2116 B] 1678s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted arm64 Packages [43.9 kB] 1678s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted arm64 c-n-f Metadata [364 B] 1678s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe arm64 Packages [461 kB] 1678s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe arm64 c-n-f Metadata [8752 B] 1678s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse arm64 Packages [8204 B] 1678s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse arm64 c-n-f Metadata [276 B] 1683s Fetched 1241 kB in 5s (237 kB/s) 1684s Reading package lists... 1701s Reading package lists... 1701s Building dependency tree... 1701s Reading state information... 1702s Calculating upgrade... 1702s The following packages will be upgraded: 1702s gcc-14-base gdisk libgcc-s1 libpython3-stdlib libstdc++6 netcat-openbsd 1702s python3 python3-gdbm python3-minimal systemd-hwe-hwdb 1703s 10 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1703s Need to get 1235 kB of archives. 1703s After this operation, 71.7 kB of additional disk space will be used. 1703s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main arm64 python3-minimal arm64 3.12.4-1 [27.1 kB] 1703s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main arm64 python3 arm64 3.12.4-1 [24.0 kB] 1703s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main arm64 libpython3-stdlib arm64 3.12.4-1 [9824 B] 1703s Get:4 http://ftpmaster.internal/ubuntu oracular/main arm64 gcc-14-base arm64 14.1.0-5ubuntu1 [49.9 kB] 1703s Get:5 http://ftpmaster.internal/ubuntu oracular/main arm64 libstdc++6 arm64 14.1.0-5ubuntu1 [749 kB] 1703s Get:6 http://ftpmaster.internal/ubuntu oracular/main arm64 libgcc-s1 arm64 14.1.0-5ubuntu1 [61.8 kB] 1703s Get:7 http://ftpmaster.internal/ubuntu oracular/main arm64 netcat-openbsd arm64 1.226-1.1 [43.3 kB] 1703s Get:8 http://ftpmaster.internal/ubuntu oracular/main arm64 systemd-hwe-hwdb all 256.2.1 [3210 B] 1703s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main arm64 python3-gdbm arm64 3.12.4-2 [18.0 kB] 1703s Get:10 http://ftpmaster.internal/ubuntu oracular/main arm64 gdisk arm64 1.0.10-2 [249 kB] 1714s Fetched 1235 kB in 1s (1335 kB/s) 1716s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 78393 files and directories currently installed.) 1716s Preparing to unpack .../python3-minimal_3.12.4-1_arm64.deb ... 1716s Unpacking python3-minimal (3.12.4-1) over (3.12.3-0ubuntu1) ... 1718s Setting up python3-minimal (3.12.4-1) ... 1721s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 78393 files and directories currently installed.) 1721s Preparing to unpack .../python3_3.12.4-1_arm64.deb ... 1722s Unpacking python3 (3.12.4-1) over (3.12.3-0ubuntu1) ... 1726s Preparing to unpack .../libpython3-stdlib_3.12.4-1_arm64.deb ... 1726s Unpacking libpython3-stdlib:arm64 (3.12.4-1) over (3.12.3-0ubuntu1) ... 1730s Preparing to unpack .../gcc-14-base_14.1.0-5ubuntu1_arm64.deb ... 1730s Unpacking gcc-14-base:arm64 (14.1.0-5ubuntu1) over (14.1.0-4ubuntu2) ... 1732s Setting up gcc-14-base:arm64 (14.1.0-5ubuntu1) ... 1733s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 78393 files and directories currently installed.) 1733s Preparing to unpack .../libstdc++6_14.1.0-5ubuntu1_arm64.deb ... 1734s Unpacking libstdc++6:arm64 (14.1.0-5ubuntu1) over (14.1.0-4ubuntu2) ... 1736s Setting up libstdc++6:arm64 (14.1.0-5ubuntu1) ... 1737s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 78393 files and directories currently installed.) 1737s Preparing to unpack .../libgcc-s1_14.1.0-5ubuntu1_arm64.deb ... 1737s Unpacking libgcc-s1:arm64 (14.1.0-5ubuntu1) over (14.1.0-4ubuntu2) ... 1740s Setting up libgcc-s1:arm64 (14.1.0-5ubuntu1) ... 1741s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 78393 files and directories currently installed.) 1741s Preparing to unpack .../netcat-openbsd_1.226-1.1_arm64.deb ... 1741s Unpacking netcat-openbsd (1.226-1.1) over (1.226-1ubuntu2) ... 1745s Preparing to unpack .../systemd-hwe-hwdb_256.2.1_all.deb ... 1745s Unpacking systemd-hwe-hwdb (256.2.1) over (255.1.3) ... 1749s Preparing to unpack .../python3-gdbm_3.12.4-2_arm64.deb ... 1749s Unpacking python3-gdbm:arm64 (3.12.4-2) over (3.12.3-0ubuntu1) ... 1756s Preparing to unpack .../gdisk_1.0.10-2_arm64.deb ... 1756s Unpacking gdisk (1.0.10-2) over (1.0.10-1build1) ... 1759s Setting up netcat-openbsd (1.226-1.1) ... 1760s Setting up gdisk (1.0.10-2) ... 1760s Setting up systemd-hwe-hwdb (256.2.1) ... 1761s Setting up libpython3-stdlib:arm64 (3.12.4-1) ... 1761s Setting up python3 (3.12.4-1) ... 1767s Setting up python3-gdbm:arm64 (3.12.4-2) ... 1767s Processing triggers for man-db (2.12.1-2) ... 1774s Processing triggers for udev (256-1ubuntu1) ... 1774s Processing triggers for libc-bin (2.39-0ubuntu9) ... 1781s Reading package lists... 1782s Building dependency tree... 1782s Reading state information... 1783s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1790s Hit:1 http://ftpmaster.internal/ubuntu oracular InRelease 1790s Hit:2 http://ftpmaster.internal/ubuntu oracular-updates InRelease 1790s Hit:3 http://ftpmaster.internal/ubuntu oracular-security InRelease 1790s Hit:4 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 1812s Reading package lists... 1813s Reading package lists... 1813s Building dependency tree... 1813s Reading state information... 1813s Calculating upgrade... 1814s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1814s Reading package lists... 1815s Building dependency tree... 1815s Reading state information... 1815s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1846s Reading package lists... 1848s Building dependency tree... 1848s Reading state information... 1849s Starting pkgProblemResolver with broken count: 0 1849s Starting 2 pkgProblemResolver with broken count: 0 1849s Done 1849s The following additional packages will be installed: 1849s build-essential cpp cpp-13 cpp-13-aarch64-linux-gnu cpp-aarch64-linux-gnu 1849s g++ g++-13 g++-13-aarch64-linux-gnu g++-aarch64-linux-gnu gcc gcc-13 1849s gcc-13-aarch64-linux-gnu gcc-aarch64-linux-gnu libasan8 libatomic1 libblas3 1849s libcc1-0 libgcc-13-dev libgfortran5 libgomp1 libhwasan0 libisl23 libitm1 1849s liblapack3 liblsan0 libmpc3 libslow5-0t64 libslow5-dev libstdc++-13-dev 1849s libstreamvbyte-dev libstreamvbyte0 libtsan2 libubsan1 python3-numpy 1849s python3-slow5 zlib1g-dev 1849s Suggested packages: 1849s cpp-doc gcc-13-locales cpp-13-doc gcc-13-doc gcc-multilib manpages-dev 1849s autoconf automake libtool flex bison gdb gcc-doc gdb-aarch64-linux-gnu 1849s libstdc++-13-doc gfortran python-numpy-doc python3-dev python3-pytest 1850s The following NEW packages will be installed: 1850s autopkgtest-satdep build-essential cpp cpp-13 cpp-13-aarch64-linux-gnu 1850s cpp-aarch64-linux-gnu g++ g++-13 g++-13-aarch64-linux-gnu 1850s g++-aarch64-linux-gnu gcc gcc-13 gcc-13-aarch64-linux-gnu 1850s gcc-aarch64-linux-gnu libasan8 libatomic1 libblas3 libcc1-0 libgcc-13-dev 1850s libgfortran5 libgomp1 libhwasan0 libisl23 libitm1 liblapack3 liblsan0 1850s libmpc3 libslow5-0t64 libslow5-dev libstdc++-13-dev libstreamvbyte-dev 1850s libstreamvbyte0 libtsan2 libubsan1 python3-numpy python3-slow5 zlib1g-dev 1851s 0 upgraded, 37 newly installed, 0 to remove and 0 not upgraded. 1851s Need to get 62.9 MB/62.9 MB of archives. 1851s After this operation, 225 MB of additional disk space will be used. 1851s Get:1 /tmp/autopkgtest.BmBxSK/2-autopkgtest-satdep.deb autopkgtest-satdep arm64 0 [756 B] 1852s Get:2 http://ftpmaster.internal/ubuntu oracular/main arm64 libisl23 arm64 0.26-3build1 [669 kB] 1852s Get:3 http://ftpmaster.internal/ubuntu oracular/main arm64 libmpc3 arm64 1.3.1-1build1 [56.4 kB] 1852s Get:4 http://ftpmaster.internal/ubuntu oracular/main arm64 cpp-13-aarch64-linux-gnu arm64 13.3.0-3ubuntu1 [9535 kB] 1853s Get:5 http://ftpmaster.internal/ubuntu oracular/main arm64 cpp-13 arm64 13.3.0-3ubuntu1 [1028 B] 1853s Get:6 http://ftpmaster.internal/ubuntu oracular/main arm64 cpp-aarch64-linux-gnu arm64 4:13.3.0-2ubuntu2 [5394 B] 1853s Get:7 http://ftpmaster.internal/ubuntu oracular/main arm64 cpp arm64 4:13.3.0-2ubuntu2 [22.4 kB] 1853s Get:8 http://ftpmaster.internal/ubuntu oracular/main arm64 libcc1-0 arm64 14.1.0-5ubuntu1 [49.6 kB] 1853s Get:9 http://ftpmaster.internal/ubuntu oracular/main arm64 libgomp1 arm64 14.1.0-5ubuntu1 [145 kB] 1853s Get:10 http://ftpmaster.internal/ubuntu oracular/main arm64 libitm1 arm64 14.1.0-5ubuntu1 [27.9 kB] 1853s Get:11 http://ftpmaster.internal/ubuntu oracular/main arm64 libatomic1 arm64 14.1.0-5ubuntu1 [11.5 kB] 1853s Get:12 http://ftpmaster.internal/ubuntu oracular/main arm64 libasan8 arm64 14.1.0-5ubuntu1 [2894 kB] 1853s Get:13 http://ftpmaster.internal/ubuntu oracular/main arm64 liblsan0 arm64 14.1.0-5ubuntu1 [1283 kB] 1853s Get:14 http://ftpmaster.internal/ubuntu oracular/main arm64 libtsan2 arm64 14.1.0-5ubuntu1 [2685 kB] 1853s Get:15 http://ftpmaster.internal/ubuntu oracular/main arm64 libubsan1 arm64 14.1.0-5ubuntu1 [1152 kB] 1853s Get:16 http://ftpmaster.internal/ubuntu oracular/main arm64 libhwasan0 arm64 14.1.0-5ubuntu1 [1598 kB] 1853s Get:17 http://ftpmaster.internal/ubuntu oracular/main arm64 libgcc-13-dev arm64 13.3.0-3ubuntu1 [2456 kB] 1853s Get:18 http://ftpmaster.internal/ubuntu oracular/main arm64 gcc-13-aarch64-linux-gnu arm64 13.3.0-3ubuntu1 [18.7 MB] 1853s Get:19 http://ftpmaster.internal/ubuntu oracular/main arm64 gcc-13 arm64 13.3.0-3ubuntu1 [482 kB] 1853s Get:20 http://ftpmaster.internal/ubuntu oracular/main arm64 gcc-aarch64-linux-gnu arm64 4:13.3.0-2ubuntu2 [1210 B] 1853s Get:21 http://ftpmaster.internal/ubuntu oracular/main arm64 gcc arm64 4:13.3.0-2ubuntu2 [5014 B] 1853s Get:22 http://ftpmaster.internal/ubuntu oracular/main arm64 libstdc++-13-dev arm64 13.3.0-3ubuntu1 [2392 kB] 1854s Get:23 http://ftpmaster.internal/ubuntu oracular/main arm64 g++-13-aarch64-linux-gnu arm64 13.3.0-3ubuntu1 [10.9 MB] 1854s Get:24 http://ftpmaster.internal/ubuntu oracular/main arm64 g++-13 arm64 13.3.0-3ubuntu1 [16.0 kB] 1854s Get:25 http://ftpmaster.internal/ubuntu oracular/main arm64 g++-aarch64-linux-gnu arm64 4:13.3.0-2ubuntu2 [962 B] 1854s Get:26 http://ftpmaster.internal/ubuntu oracular/main arm64 g++ arm64 4:13.3.0-2ubuntu2 [1080 B] 1854s Get:27 http://ftpmaster.internal/ubuntu oracular/main arm64 build-essential arm64 12.10ubuntu1 [4932 B] 1854s Get:28 http://ftpmaster.internal/ubuntu oracular/main arm64 libblas3 arm64 3.12.0-3build1 [143 kB] 1854s Get:29 http://ftpmaster.internal/ubuntu oracular/main arm64 libgfortran5 arm64 14.1.0-5ubuntu1 [438 kB] 1854s Get:30 http://ftpmaster.internal/ubuntu oracular/main arm64 liblapack3 arm64 3.12.0-3build1 [2241 kB] 1854s Get:31 http://ftpmaster.internal/ubuntu oracular/universe arm64 libslow5-0t64 arm64 0.7.0+dfsg-2.1build1 [61.9 kB] 1854s Get:32 http://ftpmaster.internal/ubuntu oracular/universe arm64 libslow5-dev arm64 0.7.0+dfsg-2.1build1 [90.3 kB] 1854s Get:33 http://ftpmaster.internal/ubuntu oracular/universe arm64 libstreamvbyte0 arm64 0.4.1-4ubuntu1 [6260 B] 1854s Get:34 http://ftpmaster.internal/ubuntu oracular/universe arm64 libstreamvbyte-dev arm64 0.4.1-4ubuntu1 [6620 B] 1854s Get:35 http://ftpmaster.internal/ubuntu oracular/main arm64 python3-numpy arm64 1:1.26.4+ds-10 [3565 kB] 1854s Get:36 http://ftpmaster.internal/ubuntu oracular/universe arm64 python3-slow5 arm64 0.7.0+dfsg-2.1build1 [452 kB] 1854s Get:37 http://ftpmaster.internal/ubuntu oracular/main arm64 zlib1g-dev arm64 1:1.3.dfsg-3.1ubuntu2 [894 kB] 1867s Fetched 62.9 MB in 4s (16.8 MB/s) 1868s Selecting previously unselected package libisl23:arm64. 1869s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 78396 files and directories currently installed.) 1869s Preparing to unpack .../00-libisl23_0.26-3build1_arm64.deb ... 1869s Unpacking libisl23:arm64 (0.26-3build1) ... 1870s Selecting previously unselected package libmpc3:arm64. 1874s Preparing to unpack .../01-libmpc3_1.3.1-1build1_arm64.deb ... 1874s Unpacking libmpc3:arm64 (1.3.1-1build1) ... 1875s Selecting previously unselected package cpp-13-aarch64-linux-gnu. 1879s Preparing to unpack .../02-cpp-13-aarch64-linux-gnu_13.3.0-3ubuntu1_arm64.deb ... 1879s Unpacking cpp-13-aarch64-linux-gnu (13.3.0-3ubuntu1) ... 1880s Selecting previously unselected package cpp-13. 1884s Preparing to unpack .../03-cpp-13_13.3.0-3ubuntu1_arm64.deb ... 1884s Unpacking cpp-13 (13.3.0-3ubuntu1) ... 1885s Selecting previously unselected package cpp-aarch64-linux-gnu. 1889s Preparing to unpack .../04-cpp-aarch64-linux-gnu_4%3a13.3.0-2ubuntu2_arm64.deb ... 1889s Unpacking cpp-aarch64-linux-gnu (4:13.3.0-2ubuntu2) ... 1889s Selecting previously unselected package cpp. 1893s Preparing to unpack .../05-cpp_4%3a13.3.0-2ubuntu2_arm64.deb ... 1894s Unpacking cpp (4:13.3.0-2ubuntu2) ... 1895s Selecting previously unselected package libcc1-0:arm64. 1900s Preparing to unpack .../06-libcc1-0_14.1.0-5ubuntu1_arm64.deb ... 1900s Unpacking libcc1-0:arm64 (14.1.0-5ubuntu1) ... 1901s Selecting previously unselected package libgomp1:arm64. 1905s Preparing to unpack .../07-libgomp1_14.1.0-5ubuntu1_arm64.deb ... 1905s Unpacking libgomp1:arm64 (14.1.0-5ubuntu1) ... 1906s Selecting previously unselected package libitm1:arm64. 1912s Preparing to unpack .../08-libitm1_14.1.0-5ubuntu1_arm64.deb ... 1912s Unpacking libitm1:arm64 (14.1.0-5ubuntu1) ... 1913s Selecting previously unselected package libatomic1:arm64. 1916s Preparing to unpack .../09-libatomic1_14.1.0-5ubuntu1_arm64.deb ... 1916s Unpacking libatomic1:arm64 (14.1.0-5ubuntu1) ... 1916s Selecting previously unselected package libasan8:arm64. 1920s Preparing to unpack .../10-libasan8_14.1.0-5ubuntu1_arm64.deb ... 1920s Unpacking libasan8:arm64 (14.1.0-5ubuntu1) ... 1921s Selecting previously unselected package liblsan0:arm64. 1924s Preparing to unpack .../11-liblsan0_14.1.0-5ubuntu1_arm64.deb ... 1924s Unpacking liblsan0:arm64 (14.1.0-5ubuntu1) ... 1924s Selecting previously unselected package libtsan2:arm64. 1927s Preparing to unpack .../12-libtsan2_14.1.0-5ubuntu1_arm64.deb ... 1927s Unpacking libtsan2:arm64 (14.1.0-5ubuntu1) ... 1927s Selecting previously unselected package libubsan1:arm64. 1930s Preparing to unpack .../13-libubsan1_14.1.0-5ubuntu1_arm64.deb ... 1930s Unpacking libubsan1:arm64 (14.1.0-5ubuntu1) ... 1930s Selecting previously unselected package libhwasan0:arm64. 1933s Preparing to unpack .../14-libhwasan0_14.1.0-5ubuntu1_arm64.deb ... 1933s Unpacking libhwasan0:arm64 (14.1.0-5ubuntu1) ... 1933s Selecting previously unselected package libgcc-13-dev:arm64. 1936s Preparing to unpack .../15-libgcc-13-dev_13.3.0-3ubuntu1_arm64.deb ... 1936s Unpacking libgcc-13-dev:arm64 (13.3.0-3ubuntu1) ... 1936s Selecting previously unselected package gcc-13-aarch64-linux-gnu. 1938s Preparing to unpack .../16-gcc-13-aarch64-linux-gnu_13.3.0-3ubuntu1_arm64.deb ... 1938s Unpacking gcc-13-aarch64-linux-gnu (13.3.0-3ubuntu1) ... 1939s Selecting previously unselected package gcc-13. 1941s Preparing to unpack .../17-gcc-13_13.3.0-3ubuntu1_arm64.deb ... 1941s Unpacking gcc-13 (13.3.0-3ubuntu1) ... 1941s Selecting previously unselected package gcc-aarch64-linux-gnu. 1943s Preparing to unpack .../18-gcc-aarch64-linux-gnu_4%3a13.3.0-2ubuntu2_arm64.deb ... 1943s Unpacking gcc-aarch64-linux-gnu (4:13.3.0-2ubuntu2) ... 1944s Selecting previously unselected package gcc. 1948s Preparing to unpack .../19-gcc_4%3a13.3.0-2ubuntu2_arm64.deb ... 1948s Unpacking gcc (4:13.3.0-2ubuntu2) ... 1949s Selecting previously unselected package libstdc++-13-dev:arm64. 1952s Preparing to unpack .../20-libstdc++-13-dev_13.3.0-3ubuntu1_arm64.deb ... 1952s Unpacking libstdc++-13-dev:arm64 (13.3.0-3ubuntu1) ... 1953s Selecting previously unselected package g++-13-aarch64-linux-gnu. 1955s Preparing to unpack .../21-g++-13-aarch64-linux-gnu_13.3.0-3ubuntu1_arm64.deb ... 1955s Unpacking g++-13-aarch64-linux-gnu (13.3.0-3ubuntu1) ... 1956s Selecting previously unselected package g++-13. 1963s Preparing to unpack .../22-g++-13_13.3.0-3ubuntu1_arm64.deb ... 1963s Unpacking g++-13 (13.3.0-3ubuntu1) ... 1964s Selecting previously unselected package g++-aarch64-linux-gnu. 1969s Preparing to unpack .../23-g++-aarch64-linux-gnu_4%3a13.3.0-2ubuntu2_arm64.deb ... 1969s Unpacking g++-aarch64-linux-gnu (4:13.3.0-2ubuntu2) ... 1970s Selecting previously unselected package g++. 1973s Preparing to unpack .../24-g++_4%3a13.3.0-2ubuntu2_arm64.deb ... 1973s Unpacking g++ (4:13.3.0-2ubuntu2) ... 1974s Selecting previously unselected package build-essential. 1977s Preparing to unpack .../25-build-essential_12.10ubuntu1_arm64.deb ... 1977s Unpacking build-essential (12.10ubuntu1) ... 1978s Selecting previously unselected package libblas3:arm64. 1981s Preparing to unpack .../26-libblas3_3.12.0-3build1_arm64.deb ... 1981s Unpacking libblas3:arm64 (3.12.0-3build1) ... 1982s Selecting previously unselected package libgfortran5:arm64. 1986s Preparing to unpack .../27-libgfortran5_14.1.0-5ubuntu1_arm64.deb ... 1986s Unpacking libgfortran5:arm64 (14.1.0-5ubuntu1) ... 1986s Selecting previously unselected package liblapack3:arm64. 1990s Preparing to unpack .../28-liblapack3_3.12.0-3build1_arm64.deb ... 1990s Unpacking liblapack3:arm64 (3.12.0-3build1) ... 1990s Selecting previously unselected package libslow5-0t64:arm64. 1994s Preparing to unpack .../29-libslow5-0t64_0.7.0+dfsg-2.1build1_arm64.deb ... 1994s Unpacking libslow5-0t64:arm64 (0.7.0+dfsg-2.1build1) ... 1994s Selecting previously unselected package libslow5-dev:arm64. 1997s Preparing to unpack .../30-libslow5-dev_0.7.0+dfsg-2.1build1_arm64.deb ... 1997s Unpacking libslow5-dev:arm64 (0.7.0+dfsg-2.1build1) ... 1998s Selecting previously unselected package libstreamvbyte0:arm64. 2001s Preparing to unpack .../31-libstreamvbyte0_0.4.1-4ubuntu1_arm64.deb ... 2001s Unpacking libstreamvbyte0:arm64 (0.4.1-4ubuntu1) ... 2002s Selecting previously unselected package libstreamvbyte-dev:arm64. 2007s Preparing to unpack .../32-libstreamvbyte-dev_0.4.1-4ubuntu1_arm64.deb ... 2007s Unpacking libstreamvbyte-dev:arm64 (0.4.1-4ubuntu1) ... 2008s Selecting previously unselected package python3-numpy. 2012s Preparing to unpack .../33-python3-numpy_1%3a1.26.4+ds-10_arm64.deb ... 2012s Unpacking python3-numpy (1:1.26.4+ds-10) ... 2013s Selecting previously unselected package python3-slow5. 2017s Preparing to unpack .../34-python3-slow5_0.7.0+dfsg-2.1build1_arm64.deb ... 2017s Unpacking python3-slow5 (0.7.0+dfsg-2.1build1) ... 2018s Selecting previously unselected package zlib1g-dev:arm64. 2022s Preparing to unpack .../35-zlib1g-dev_1%3a1.3.dfsg-3.1ubuntu2_arm64.deb ... 2022s Unpacking zlib1g-dev:arm64 (1:1.3.dfsg-3.1ubuntu2) ... 2023s Selecting previously unselected package autopkgtest-satdep. 2027s Preparing to unpack .../36-2-autopkgtest-satdep.deb ... 2027s Unpacking autopkgtest-satdep (0) ... 2032s Setting up libstreamvbyte0:arm64 (0.4.1-4ubuntu1) ... 2032s Setting up libgomp1:arm64 (14.1.0-5ubuntu1) ... 2032s Setting up libblas3:arm64 (3.12.0-3build1) ... 2032s update-alternatives: using /usr/lib/aarch64-linux-gnu/blas/libblas.so.3 to provide /usr/lib/aarch64-linux-gnu/libblas.so.3 (libblas.so.3-aarch64-linux-gnu) in auto mode 2032s Setting up libstreamvbyte-dev:arm64 (0.4.1-4ubuntu1) ... 2032s Setting up libmpc3:arm64 (1.3.1-1build1) ... 2032s Setting up libatomic1:arm64 (14.1.0-5ubuntu1) ... 2032s Setting up libslow5-0t64:arm64 (0.7.0+dfsg-2.1build1) ... 2032s Setting up libgfortran5:arm64 (14.1.0-5ubuntu1) ... 2032s Setting up libubsan1:arm64 (14.1.0-5ubuntu1) ... 2032s Setting up zlib1g-dev:arm64 (1:1.3.dfsg-3.1ubuntu2) ... 2032s Setting up libhwasan0:arm64 (14.1.0-5ubuntu1) ... 2032s Setting up libasan8:arm64 (14.1.0-5ubuntu1) ... 2032s Setting up libtsan2:arm64 (14.1.0-5ubuntu1) ... 2032s Setting up libisl23:arm64 (0.26-3build1) ... 2032s Setting up libcc1-0:arm64 (14.1.0-5ubuntu1) ... 2032s Setting up liblsan0:arm64 (14.1.0-5ubuntu1) ... 2032s Setting up libitm1:arm64 (14.1.0-5ubuntu1) ... 2032s Setting up liblapack3:arm64 (3.12.0-3build1) ... 2032s update-alternatives: using /usr/lib/aarch64-linux-gnu/lapack/liblapack.so.3 to provide /usr/lib/aarch64-linux-gnu/liblapack.so.3 (liblapack.so.3-aarch64-linux-gnu) in auto mode 2032s Setting up cpp-13-aarch64-linux-gnu (13.3.0-3ubuntu1) ... 2032s Setting up libslow5-dev:arm64 (0.7.0+dfsg-2.1build1) ... 2032s Setting up cpp-aarch64-linux-gnu (4:13.3.0-2ubuntu2) ... 2032s Setting up python3-numpy (1:1.26.4+ds-10) ... 2037s Setting up libgcc-13-dev:arm64 (13.3.0-3ubuntu1) ... 2037s Setting up libstdc++-13-dev:arm64 (13.3.0-3ubuntu1) ... 2037s Setting up cpp-13 (13.3.0-3ubuntu1) ... 2037s Setting up gcc-13-aarch64-linux-gnu (13.3.0-3ubuntu1) ... 2037s Setting up gcc-13 (13.3.0-3ubuntu1) ... 2037s Setting up python3-slow5 (0.7.0+dfsg-2.1build1) ... 2037s Setting up cpp (4:13.3.0-2ubuntu2) ... 2038s Setting up g++-13-aarch64-linux-gnu (13.3.0-3ubuntu1) ... 2038s Setting up gcc-aarch64-linux-gnu (4:13.3.0-2ubuntu2) ... 2038s Setting up g++-13 (13.3.0-3ubuntu1) ... 2038s Setting up gcc (4:13.3.0-2ubuntu2) ... 2038s Setting up g++-aarch64-linux-gnu (4:13.3.0-2ubuntu2) ... 2038s Setting up g++ (4:13.3.0-2ubuntu2) ... 2038s update-alternatives: using /usr/bin/g++ to provide /usr/bin/c++ (c++) in auto mode 2038s Setting up build-essential (12.10ubuntu1) ... 2038s Setting up autopkgtest-satdep (0) ... 2038s Processing triggers for man-db (2.12.1-2) ... 2050s Processing triggers for libc-bin (2.39-0ubuntu9) ... 2075s (Reading database ... 80505 files and directories currently installed.) 2075s Removing autopkgtest-satdep (0) ... 2083s autopkgtest [02:07:07]: test run-pkg-test: [----------------------- 2086s Checking unit_test_ascii.c 2100s Done! 2100s Checking unit_test_binary.c 2100s Done! 2100s Checking unit_test_empty.c 2101s Done! 2101s Checking unit_test_enum.c 2101s Done! 2101s Checking unit_test_helpers.c 2102s Done! 2102s Checking unit_test_lossless.c 2102s Done! 2102s Checking unit_test_press.c 2103s Done! 2103s Checking unit_test_two_rg.c 2104s Done! 2106s autopkgtest [02:07:30]: test run-pkg-test: -----------------------] 2108s autopkgtest [02:07:32]: test run-pkg-test: - - - - - - - - - - results - - - - - - - - - - 2108s run-pkg-test PASS 2109s autopkgtest [02:07:33]: @@@@@@@@@@@@@@@@@@@@ summary 2109s run-pybinding-test PASS 2109s run-pkg-test PASS 2447s nova [W] Skipping flock in bos03-arm64 2447s Creating nova instance adt-oracular-arm64-libslow5lib-20240723-013224-juju-7f2275-prod-proposed-migration-environment-2-7f0cfebe-9b92-4e94-a748-6f8cf9275ffc from image adt/ubuntu-oracular-arm64-server-20240721.img (UUID 82bde252-f2f6-4a5f-8912-308e3b0a85c9)... 2447s nova [W] Skipping flock in bos03-arm64 2447s Creating nova instance adt-oracular-arm64-libslow5lib-20240723-013224-juju-7f2275-prod-proposed-migration-environment-2-7f0cfebe-9b92-4e94-a748-6f8cf9275ffc from image adt/ubuntu-oracular-arm64-server-20240721.img (UUID 82bde252-f2f6-4a5f-8912-308e3b0a85c9)...