0s autopkgtest [22:24:01]: starting date and time: 2024-07-21 22:24:01+0000 0s autopkgtest [22:24:01]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [22:24:01]: host juju-7f2275-prod-proposed-migration-environment-9; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work._qvt2lnb/out --timeout-copy=6000 --setup-commands 'ln -s /dev/null /etc/systemd/system/bluetooth.service; printf "http_proxy=http://squid.internal:3128\nhttps_proxy=http://squid.internal:3128\nno_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\n" >> /etc/environment' --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' -- lxd -r lxd-armhf-10.145.243.222 lxd-armhf-10.145.243.222:autopkgtest/ubuntu/oracular/armhf 57s autopkgtest [22:24:58]: testbed dpkg architecture: armhf 58s autopkgtest [22:24:59]: testbed apt version: 2.9.6 58s autopkgtest [22:24:59]: @@@@@@@@@@@@@@@@@@@@ test bed setup 78s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 80s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [62.0 kB] 81s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3440 B] 81s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 81s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [393 kB] 81s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main armhf Packages [89.4 kB] 81s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main armhf c-n-f Metadata [1428 B] 81s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted armhf Packages [1368 B] 81s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted armhf c-n-f Metadata [120 B] 81s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe armhf Packages [327 kB] 81s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe armhf c-n-f Metadata [6916 B] 81s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse armhf Packages [2072 B] 81s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse armhf c-n-f Metadata [120 B] 84s Fetched 1021 kB in 4s (277 kB/s) 85s Reading package lists... 105s tee: /proc/self/fd/2: Permission denied 134s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 134s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 134s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 134s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 141s Reading package lists... 141s Reading package lists... 142s Building dependency tree... 142s Reading state information... 142s Calculating upgrade... 143s The following packages will be upgraded: 143s cloud-init gdisk libbpf1 libpython3-stdlib libudisks2-0 libxml2 143s netcat-openbsd python3 python3-gdbm python3-minimal udisks2 143s 11 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 143s Need to get 2072 kB of archives. 143s After this operation, 30.7 kB disk space will be freed. 143s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main armhf python3-minimal armhf 3.12.4-1 [27.1 kB] 144s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main armhf python3 armhf 3.12.4-1 [24.0 kB] 144s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main armhf libpython3-stdlib armhf 3.12.4-1 [9824 B] 144s Get:4 http://ftpmaster.internal/ubuntu oracular/main armhf libbpf1 armhf 1:1.4.5-1 [151 kB] 144s Get:5 http://ftpmaster.internal/ubuntu oracular/main armhf libxml2 armhf 2.12.7+dfsg-3 [560 kB] 144s Get:6 http://ftpmaster.internal/ubuntu oracular/main armhf netcat-openbsd armhf 1.226-1.1 [42.2 kB] 144s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main armhf python3-gdbm armhf 3.12.4-2 [16.9 kB] 144s Get:8 http://ftpmaster.internal/ubuntu oracular/main armhf udisks2 armhf 2.10.1-9ubuntu1 [277 kB] 144s Get:9 http://ftpmaster.internal/ubuntu oracular/main armhf libudisks2-0 armhf 2.10.1-9ubuntu1 [142 kB] 144s Get:10 http://ftpmaster.internal/ubuntu oracular/main armhf cloud-init all 24.3~1g6e4153b3-0ubuntu1 [592 kB] 144s Get:11 http://ftpmaster.internal/ubuntu oracular/main armhf gdisk armhf 1.0.10-2 [229 kB] 145s Preconfiguring packages ... 146s Fetched 2072 kB in 1s (2425 kB/s) 146s (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 ... 58436 files and directories currently installed.) 146s Preparing to unpack .../python3-minimal_3.12.4-1_armhf.deb ... 146s Unpacking python3-minimal (3.12.4-1) over (3.12.3-0ubuntu1) ... 146s Setting up python3-minimal (3.12.4-1) ... 146s (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 ... 58436 files and directories currently installed.) 146s Preparing to unpack .../0-python3_3.12.4-1_armhf.deb ... 147s Unpacking python3 (3.12.4-1) over (3.12.3-0ubuntu1) ... 147s Preparing to unpack .../1-libpython3-stdlib_3.12.4-1_armhf.deb ... 147s Unpacking libpython3-stdlib:armhf (3.12.4-1) over (3.12.3-0ubuntu1) ... 147s Preparing to unpack .../2-libbpf1_1%3a1.4.5-1_armhf.deb ... 147s Unpacking libbpf1:armhf (1:1.4.5-1) over (1:1.4.3-1) ... 147s Preparing to unpack .../3-libxml2_2.12.7+dfsg-3_armhf.deb ... 147s Unpacking libxml2:armhf (2.12.7+dfsg-3) over (2.9.14+dfsg-1.3ubuntu3) ... 148s Preparing to unpack .../4-netcat-openbsd_1.226-1.1_armhf.deb ... 148s Unpacking netcat-openbsd (1.226-1.1) over (1.226-1ubuntu2) ... 148s Preparing to unpack .../5-python3-gdbm_3.12.4-2_armhf.deb ... 148s Unpacking python3-gdbm:armhf (3.12.4-2) over (3.12.3-0ubuntu1) ... 148s Preparing to unpack .../6-udisks2_2.10.1-9ubuntu1_armhf.deb ... 148s Unpacking udisks2 (2.10.1-9ubuntu1) over (2.10.1-9) ... 148s Preparing to unpack .../7-libudisks2-0_2.10.1-9ubuntu1_armhf.deb ... 148s Unpacking libudisks2-0:armhf (2.10.1-9ubuntu1) over (2.10.1-9) ... 148s Preparing to unpack .../8-cloud-init_24.3~1g6e4153b3-0ubuntu1_all.deb ... 149s Unpacking cloud-init (24.3~1g6e4153b3-0ubuntu1) over (24.2-0ubuntu1) ... 149s Preparing to unpack .../9-gdisk_1.0.10-2_armhf.deb ... 149s Unpacking gdisk (1.0.10-2) over (1.0.10-1build1) ... 150s Setting up netcat-openbsd (1.226-1.1) ... 150s Setting up gdisk (1.0.10-2) ... 150s Setting up libxml2:armhf (2.12.7+dfsg-3) ... 150s Setting up libbpf1:armhf (1:1.4.5-1) ... 150s Setting up libudisks2-0:armhf (2.10.1-9ubuntu1) ... 150s Setting up libpython3-stdlib:armhf (3.12.4-1) ... 150s Setting up udisks2 (2.10.1-9ubuntu1) ... 150s vda: Failed to write 'change' to '/sys/devices/pci0000:00/0000:00:01.3/0000:04:00.0/virtio2/block/vda/uevent': Permission denied 150s vda1: Failed to write 'change' to '/sys/devices/pci0000:00/0000:00:01.3/0000:04:00.0/virtio2/block/vda/vda1/uevent': Permission denied 150s vda15: Failed to write 'change' to '/sys/devices/pci0000:00/0000:00:01.3/0000:04:00.0/virtio2/block/vda/vda15/uevent': Permission denied 150s vda2: Failed to write 'change' to '/sys/devices/pci0000:00/0000:00:01.3/0000:04:00.0/virtio2/block/vda/vda2/uevent': Permission denied 150s loop0: Failed to write 'change' to '/sys/devices/virtual/block/loop0/uevent': Permission denied 150s loop1: Failed to write 'change' to '/sys/devices/virtual/block/loop1/uevent': Permission denied 150s loop2: Failed to write 'change' to '/sys/devices/virtual/block/loop2/uevent': Permission denied 150s loop3: Failed to write 'change' to '/sys/devices/virtual/block/loop3/uevent': Permission denied 150s loop4: Failed to write 'change' to '/sys/devices/virtual/block/loop4/uevent': Permission denied 150s loop5: Failed to write 'change' to '/sys/devices/virtual/block/loop5/uevent': Permission denied 150s loop6: Failed to write 'change' to '/sys/devices/virtual/block/loop6/uevent': Permission denied 150s loop7: Failed to write 'change' to '/sys/devices/virtual/block/loop7/uevent': Permission denied 151s Setting up python3 (3.12.4-1) ... 152s Setting up cloud-init (24.3~1g6e4153b3-0ubuntu1) ... 154s Setting up python3-gdbm:armhf (3.12.4-2) ... 154s Processing triggers for rsyslog (8.2312.0-3ubuntu9) ... 154s Processing triggers for man-db (2.12.1-2) ... 155s Processing triggers for dbus (1.14.10-4ubuntu4) ... 155s Processing triggers for libc-bin (2.39-0ubuntu9) ... 156s Reading package lists... 156s Building dependency tree... 156s Reading state information... 157s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 159s autopkgtest [22:26:40]: rebooting testbed after setup commands that affected boot 230s autopkgtest [22:27:51]: testbed running kernel: Linux 6.5.0-41-generic #41~22.04.2-Ubuntu SMP PREEMPT_DYNAMIC Mon Jun 3 16:28:24 UTC 2 257s autopkgtest [22:28:18]: @@@@@@@@@@@@@@@@@@@@ apt-source libslow5lib 274s Get:1 http://ftpmaster.internal/ubuntu oracular/universe libslow5lib 0.7.0+dfsg-2.1build1 (dsc) [2541 B] 274s Get:2 http://ftpmaster.internal/ubuntu oracular/universe libslow5lib 0.7.0+dfsg-2.1build1 (tar) [2014 kB] 274s Get:3 http://ftpmaster.internal/ubuntu oracular/universe libslow5lib 0.7.0+dfsg-2.1build1 (diff) [8280 B] 275s gpgv: Signature made Sun Mar 31 19:37:54 2024 UTC 275s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 275s gpgv: issuer "steve.langasek@ubuntu.com" 275s gpgv: Can't check signature: No public key 275s dpkg-source: warning: cannot verify inline signature for ./libslow5lib_0.7.0+dfsg-2.1build1.dsc: no acceptable signature found 275s autopkgtest [22:28:36]: testing package libslow5lib version 0.7.0+dfsg-2.1build1 278s autopkgtest [22:28:39]: build not needed 282s autopkgtest [22:28:43]: test run-pybinding-test: preparing testbed 292s Reading package lists... 292s Building dependency tree... 292s Reading state information... 293s Starting pkgProblemResolver with broken count: 0 293s Starting 2 pkgProblemResolver with broken count: 0 293s Done 293s The following additional packages will be installed: 293s libblas3 libgfortran5 liblapack3 libslow5-0t64 libslow5-dev libstreamvbyte0 293s python3-all python3-numpy python3-slow5 293s Suggested packages: 293s gcc gfortran python-numpy-doc python3-dev python3-pytest 293s The following NEW packages will be installed: 293s autopkgtest-satdep libblas3 libgfortran5 liblapack3 libslow5-0t64 293s libslow5-dev libstreamvbyte0 python3-all python3-numpy python3-slow5 294s 0 upgraded, 10 newly installed, 0 to remove and 0 not upgraded. 294s Need to get 6674 kB/6675 kB of archives. 294s After this operation, 29.6 MB of additional disk space will be used. 294s Get:1 /tmp/autopkgtest.Jz6Pkd/1-autopkgtest-satdep.deb autopkgtest-satdep armhf 0 [728 B] 294s Get:2 http://ftpmaster.internal/ubuntu oracular/main armhf libblas3 armhf 3.12.0-3build1 [123 kB] 294s Get:3 http://ftpmaster.internal/ubuntu oracular/main armhf libgfortran5 armhf 14.1.0-4ubuntu2 [311 kB] 294s Get:4 http://ftpmaster.internal/ubuntu oracular/main armhf liblapack3 armhf 3.12.0-3build1 [2085 kB] 294s Get:5 http://ftpmaster.internal/ubuntu oracular/universe armhf libslow5-0t64 armhf 0.7.0+dfsg-2.1build1 [63.0 kB] 294s Get:6 http://ftpmaster.internal/ubuntu oracular/universe armhf libslow5-dev armhf 0.7.0+dfsg-2.1build1 [84.4 kB] 294s Get:7 http://ftpmaster.internal/ubuntu oracular/universe armhf libstreamvbyte0 armhf 0.4.1-4ubuntu1 [5742 B] 294s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main armhf python3-all armhf 3.12.4-1 [882 B] 294s Get:9 http://ftpmaster.internal/ubuntu oracular/main armhf python3-numpy armhf 1:1.26.4+ds-10 [3541 kB] 294s Get:10 http://ftpmaster.internal/ubuntu oracular/universe armhf python3-slow5 armhf 0.7.0+dfsg-2.1build1 [460 kB] 295s Fetched 6674 kB in 1s (8075 kB/s) 295s Selecting previously unselected package libblas3:armhf. 295s (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 ... 58440 files and directories currently installed.) 295s Preparing to unpack .../0-libblas3_3.12.0-3build1_armhf.deb ... 295s Unpacking libblas3:armhf (3.12.0-3build1) ... 295s Selecting previously unselected package libgfortran5:armhf. 295s Preparing to unpack .../1-libgfortran5_14.1.0-4ubuntu2_armhf.deb ... 295s Unpacking libgfortran5:armhf (14.1.0-4ubuntu2) ... 295s Selecting previously unselected package liblapack3:armhf. 295s Preparing to unpack .../2-liblapack3_3.12.0-3build1_armhf.deb ... 295s Unpacking liblapack3:armhf (3.12.0-3build1) ... 295s Selecting previously unselected package libslow5-0t64:armhf. 295s Preparing to unpack .../3-libslow5-0t64_0.7.0+dfsg-2.1build1_armhf.deb ... 295s Unpacking libslow5-0t64:armhf (0.7.0+dfsg-2.1build1) ... 295s Selecting previously unselected package libslow5-dev:armhf. 295s Preparing to unpack .../4-libslow5-dev_0.7.0+dfsg-2.1build1_armhf.deb ... 295s Unpacking libslow5-dev:armhf (0.7.0+dfsg-2.1build1) ... 296s Selecting previously unselected package libstreamvbyte0:armhf. 296s Preparing to unpack .../5-libstreamvbyte0_0.4.1-4ubuntu1_armhf.deb ... 296s Unpacking libstreamvbyte0:armhf (0.4.1-4ubuntu1) ... 296s Selecting previously unselected package python3-all. 296s Preparing to unpack .../6-python3-all_3.12.4-1_armhf.deb ... 296s Unpacking python3-all (3.12.4-1) ... 296s Selecting previously unselected package python3-numpy. 296s Preparing to unpack .../7-python3-numpy_1%3a1.26.4+ds-10_armhf.deb ... 296s Unpacking python3-numpy (1:1.26.4+ds-10) ... 296s Selecting previously unselected package python3-slow5. 296s Preparing to unpack .../8-python3-slow5_0.7.0+dfsg-2.1build1_armhf.deb ... 296s Unpacking python3-slow5 (0.7.0+dfsg-2.1build1) ... 296s Selecting previously unselected package autopkgtest-satdep. 296s Preparing to unpack .../9-1-autopkgtest-satdep.deb ... 296s Unpacking autopkgtest-satdep (0) ... 296s Setting up libstreamvbyte0:armhf (0.4.1-4ubuntu1) ... 296s Setting up python3-all (3.12.4-1) ... 296s Setting up libblas3:armhf (3.12.0-3build1) ... 296s update-alternatives: using /usr/lib/arm-linux-gnueabihf/blas/libblas.so.3 to provide /usr/lib/arm-linux-gnueabihf/libblas.so.3 (libblas.so.3-arm-linux-gnueabihf) in auto mode 296s Setting up libslow5-0t64:armhf (0.7.0+dfsg-2.1build1) ... 296s Setting up libgfortran5:armhf (14.1.0-4ubuntu2) ... 296s Setting up liblapack3:armhf (3.12.0-3build1) ... 296s update-alternatives: using /usr/lib/arm-linux-gnueabihf/lapack/liblapack.so.3 to provide /usr/lib/arm-linux-gnueabihf/liblapack.so.3 (liblapack.so.3-arm-linux-gnueabihf) in auto mode 296s Setting up libslow5-dev:armhf (0.7.0+dfsg-2.1build1) ... 296s Setting up python3-numpy (1:1.26.4+ds-10) ... 298s Setting up python3-slow5 (0.7.0+dfsg-2.1build1) ... 298s Setting up autopkgtest-satdep (0) ... 298s Processing triggers for man-db (2.12.1-2) ... 299s Processing triggers for libc-bin (2.39-0ubuntu9) ... 320s (Reading database ... 59378 files and directories currently installed.) 320s Removing autopkgtest-satdep (0) ... 326s autopkgtest [22:29:27]: test run-pybinding-test: [----------------------- 329s Testing with python3.12 in /tmp/autopkgtest.Jz6Pkd/autopkgtest_tmp: 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example.slow5, mode: r 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: b'examples/example.slow5', mode: b'r' 330s 21-Jul-24 22:29:31 - [DEBUG]: Number of read_groups: 1 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example.slow5, mode: r 330s 21-Jul-24 22:29:31 - [DEBUG]: Creating/loading index... 330s [slow5_idx_init::INFO] Index file not found. Creating an index at 'examples/example.slow5.idx'. 330s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_names starting 330s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_names aux_len: 0 330s 21-Jul-24 22:29:31 - [WARNING]: get_aux_names ret is NULL 330s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_types starting 330s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_types aux_len: 0 330s 21-Jul-24 22:29:31 - [WARNING]: get_aux_types self.s5_aux_type is NULL 330s 21-Jul-24 22:29:31 - [WARNING]: get_read unknown aux name: blah 330s 21-Jul-24 22:29:31 - [WARNING]: get_read unknown aux name: start_mux 330s 21-Jul-24 22:29:31 - [WARNING]: get_read unknown aux name: read_number 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: -1 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 330s [slow5_idx_get::ERROR] Read ID 'null_read' was not found. At src/slow5_idx.c:441 330s 21-Jul-24 22:29:31 - [DEBUG]: get_read return not 0: -7 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_hdr_keys head_len: 32 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_hdr_keys head_len: 32 330s 21-Jul-24 22:29:31 - [DEBUG]: examples/example.slow5 closed 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example2.slow5, mode: r 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 330s 21-Jul-24 22:29:31 - [DEBUG]: Number of read_groups: 4 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example2.slow5, mode: r 330s 21-Jul-24 22:29:31 - [DEBUG]: Creating/loading index... 330s [slow5_idx_init::INFO] Index file not found. Creating an index at 'examples/example2.slow5.idx'. 330s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_names starting 330s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_names aux_len: 5 330s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_types starting 330s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_types aux_len: 5 330s 21-Jul-24 22:29:31 - [WARNING]: get_read unknown aux name: blah 330s 21-Jul-24 22:29:31 - [WARNING]: get_read unknown aux name: blah 330s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_names starting 330s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_names aux_len: 5 330s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_types starting 330s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_types aux_len: 5 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: -1 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 330s 21-Jul-24 22:29:31 - [DEBUG]: examples/example2.slow5 closed 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example_write.slow5, mode: w 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: b'examples/example_write.slow5', mode: b'w' 330s 21-Jul-24 22:29:31 - [DEBUG]: Not writing blow5, skipping compression steps 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example2.slow5, mode: r 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 330s 21-Jul-24 22:29:31 - [DEBUG]: Number of read_groups: 4 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checking header stuff... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: writting header... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: header written 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 305872 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 152707 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 305872 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 152707 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 305872 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 152707 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 305906 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 152741 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: -1 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 330s 21-Jul-24 22:29:31 - [DEBUG]: examples/example_write.slow5 closed 330s 21-Jul-24 22:29:31 - [DEBUG]: examples/example2.slow5 closed 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example_write_append.blow5, mode: w 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: b'examples/example_write_append.blow5', mode: b'w' 330s 21-Jul-24 22:29:31 - [DEBUG]: examples/example_write.slow5 already closed 330s 21-Jul-24 22:29:31 - [DEBUG]: pathname: examples/example_write.slow5 330s 21-Jul-24 22:29:31 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: total_time_yield_reads: 0.0 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: total_single_write_time: 0.028600454330444336 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_time: 0.0 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example2.slow5, mode: r 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 330s 21-Jul-24 22:29:31 - [DEBUG]: Number of read_groups: 4 330s 21-Jul-24 22:29:31 - [DEBUG]: pathname: examples/example2.slow5 330s 21-Jul-24 22:29:31 - [DEBUG]: total_time_slow5_get_next: 0.021999597549438477 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: total_time_yield_reads: 0.023146867752075195 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: total_single_write_time: 0.0 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_time: 0.0 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checking header stuff... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: writting header... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: header written 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 152976 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 76384 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 152976 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 76384 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 152976 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 76384 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 153010 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 76418 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: -1 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 330s 21-Jul-24 22:29:31 - [DEBUG]: examples/example2.slow5 closed 330s 21-Jul-24 22:29:31 - [DEBUG]: examples/example_write_append.blow5 closed 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example_write_append.blow5, mode: a 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: b'examples/example_write_append.blow5', mode: b'a' 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_hdr_keys head_len: 38 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example2.slow5, mode: r 330s 21-Jul-24 22:29:31 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 330s 21-Jul-24 22:29:31 - [DEBUG]: Number of read_groups: 4 330s 21-Jul-24 22:29:31 - [DEBUG]: pathname: examples/example2.slow5 330s 21-Jul-24 22:29:31 - [DEBUG]: total_time_slow5_get_next: 0.02269911766052246 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: total_time_yield_reads: 0.023887157440185547 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: total_single_write_time: 0.0 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 330s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_time: 0.0 seconds 330s |==============================================| 330s | pyslow5 test launch | 330s |==============================================| 330s ['__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'] 330s slow5 file opened and object created in: 0.0468 seconds 330s ============================================== 330s get_read check, r1 330s get_read in: 0.0211 seconds 330s read_id: r1 330s read_group: 0 330s digitisation: 8192.0 330s offset: 23.0 330s range: 1467.61 330s sampling_rate: 4000.0 330s len_raw_signal: 59676 330s signal: [1039 588 588 593 586 574 570 585 588 586] 330s pylen of signal: 59676 330s AUX FIELDS: 330s read_number: None 330s start_mux: None 330s blah: None 330s ============================================== 330s get_read check, r4, converte to pA 330s get_read in: 0.0081 seconds 330s read_id: r4 330s read_group: 0 330s digitisation: 8192.0 330s offset: 23.0 330s range: 1467.61 330s sampling_rate: 4000.0 330s len_raw_signal: 59670 330s signal: [190.25902 108.92418 109.46163 109.10333 107.67012 108.38673 330s 108.745026 109.10333 111.074 108.38673 ] 330s pylen of signal: 59670 330s signal value type: 330s ============================================== 330s seq_reads check, all reads 330s seq_reads readIDs: 330s type check reads: 330s r1 330s r2 330s r3 330s r4 330s r5 330s seq_reads in: 0.0228 seconds 330s ============================================== 330s Yield check, selected reads 330s get_read_list in: 0.0 seconds 330s yielded readIDs: 330s r1 r1 330s r3 r3 330s null_read read not found, None returned 330s r5 r5 330s r2 r2 330s r1 r1 330s ============================================== 330s Get headder names 330s header names: 330s ['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'] 330s ============================================== 330s get_all_headers 330s {'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'} 330s ============================================== 330s Get headder attributes 330s flow_cell_id: FAB43577 330s exp_start_time: 1479433093 330s heatsink_temp: 33.9921875 330s asic_id: 3574887596 330s asic_id_eeprom: 0 330s asic_temp: 29.2145729 330s auto_update: 1 330s auto_update_source: https://mirror.oxfordnanoportal.com/software/MinKNOW/ 330s bream_core_version: 1.1.20.1 330s bream_is_standard: 1 330s bream_map_version: 1.1.20.1 330s bream_ont_version: 1.1.20.1 330s bream_prod_version: 1.1.20.1 330s bream_rnd_version: 0.1.1 330s device_id: MN16450 330s exp_script_name: python/recipes/nc/NC_48Hr_Sequencing_Run_FLO-MIN106_SQK-LSK108.py 330s exp_script_purpose: sequencing_run 330s exp_start_time: 1479433093 330s experiment_kit: genomic_dna 330s experiment_type: customer_qc 330s file_version: 1 330s filename: deamernanopore_20161117_fnfab43577_mn16450_sequencing_run_ma_821_r9_4_na12878_11_17_16_88738 330s flow_cell_id: FAB43577 330s heatsink_temp: 33.9921875 330s hostname: DEAMERNANOPORE 330s installation_type: map 330s local_firmware_file: 0 330s operating_system: Windows 6.2 330s protocol_run_id: a4429838-103c-497f-a824-7dffa72cfd81 330s protocols_version: 1.1.20 330s run_id: d6e473a6d513ec6bfc150c60fd4556d72f0e6d18 330s sample_frequency: 4000 330s usb_config: 1.0.11_ONT#MinION_fpga_1.0.1#ctrl#Auto 330s user_filename_input: ma_821_r9.4_na12878_11_17_16 330s version: 1.1.20 330s ============================================== 330s get_read check, 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 330s read_id: 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 330s read_group: 3 330s digitisation: 8192.0 330s offset: 6.0 330s range: 1444.86 330s sampling_rate: 4000.0 330s len_raw_signal: 38164 330s signal: [1462 1075 795 801 797 788 817 791 801 802] 330s pylen of signal: 38164 330s AUX FIELDS: 330s read_number: 2287 330s start_mux: 2 330s blah: None 330s AUX FIELDS: 330s blah: None 330s AUX FIELDS: 330s read_number: 2287 330s ============================================== 330s Get aux names 330s aux names: 330s ['channel_number', 'median_before', 'read_number', 'start_mux', 'start_time'] 330s ============================================== 330s Get aux types 330s aux types: 330s [22, 9, 2, 4, 7] 330s ============================================== 330s AUX FIELDS: 330s channel_number: 391 330s median_before: 260.557264 330s read_number: 2287 330s start_mux: 2 330s start_time: 36886851 330s ============================================== 330s seq_reads with aux: 330s type check reads: 330s r0 330s read_number 4019 330s r1 330s read_number 2287 330s r2 330s read_number 4019 330s r3 330s read_number 2287 330s r4 330s read_number 4019 330s r5 330s read_number 2287 330s 0a238451-b9ed-446d-a152-badd074006c4 330s read_number 4019 330s 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 330s read_number 2287 330s ============================================== 330s write reads no aux 330s ret: write_header(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s ============================================== 330s append reads no aux 330s ret: write_header(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s ret: write_record(): 0 330s get_all_headers 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 152983 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 330s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 330s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 76391 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 152983 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 76391 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 152983 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 76391 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 153017 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 76425 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: -1 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 331s 21-Jul-24 22:29:31 - [DEBUG]: examples/example2.slow5 closed 331s 21-Jul-24 22:29:31 - [DEBUG]: examples/example_write_append.blow5 closed 331s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example_write_aux.blow5, mode: w 331s 21-Jul-24 22:29:31 - [DEBUG]: FILE: b'examples/example_write_aux.blow5', mode: b'w' 331s 21-Jul-24 22:29:31 - [DEBUG]: examples/example_write_append.blow5 already closed 331s 21-Jul-24 22:29:31 - [DEBUG]: pathname: examples/example_write_append.blow5 331s 21-Jul-24 22:29:31 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_time_yield_reads: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_single_write_time: 0.028667211532592773 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example2.slow5, mode: r 331s 21-Jul-24 22:29:31 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 331s 21-Jul-24 22:29:31 - [DEBUG]: Number of read_groups: 4 331s 21-Jul-24 22:29:31 - [DEBUG]: pathname: examples/example2.slow5 331s 21-Jul-24 22:29:31 - [DEBUG]: total_time_slow5_get_next: 0.022025585174560547 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_time_yield_reads: 0.02312946319580078 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_single_write_time: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_names starting 331s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_names aux_len: 5 331s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_types starting 331s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_types aux_len: 5 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checking header stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: writting header... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: header written 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 67258 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 32408 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 67258 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 32408 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 67260 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 32408 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 67298 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 32446 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: -1 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 331s 21-Jul-24 22:29:31 - [DEBUG]: examples/example2.slow5 closed 331s 21-Jul-24 22:29:31 - [DEBUG]: examples/example_write_aux.blow5 closed 331s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example_write_append_aux.blow5, mode: w 331s 21-Jul-24 22:29:31 - [DEBUG]: FILE: b'examples/example_write_append_aux.blow5', mode: b'w' 331s 21-Jul-24 22:29:31 - [DEBUG]: examples/example_write_aux.blow5 already closed 331s 21-Jul-24 22:29:31 - [DEBUG]: pathname: examples/example_write_aux.blow5 331s 21-Jul-24 22:29:31 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_time_yield_reads: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_single_write_time: 0.028746366500854492 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: FILE: examples/example2.slow5, mode: r 331s 21-Jul-24 22:29:31 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 331s 21-Jul-24 22:29:31 - [DEBUG]: Number of read_groups: 4 331s 21-Jul-24 22:29:31 - [DEBUG]: pathname: examples/example2.slow5 331s 21-Jul-24 22:29:31 - [DEBUG]: total_time_slow5_get_next: 0.022301197052001953 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_time_yield_reads: 0.023783445358276367 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_single_write_time: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_names starting 331s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_names aux_len: 5 331s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_types starting 331s 21-Jul-24 22:29:31 - [DEBUG]: get_aux_types aux_len: 5 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checking header stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: writting header... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: header written 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 153008 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 76416 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 153008 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:31 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_write() ret: 76416 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:31 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:31 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() ret: 153008 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() ret: 76416 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() ret: 153042 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() ret: 76450 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: -1 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 331s 21-Jul-24 22:29:32 - [DEBUG]: examples/example2.slow5 closed 331s 21-Jul-24 22:29:32 - [DEBUG]: examples/example_write_append_aux.blow5 closed 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: examples/example_write_append_aux.blow5, mode: a 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: b'examples/example_write_append_aux.blow5', mode: b'a' 331s 21-Jul-24 22:29:32 - [DEBUG]: examples/example_write_append.blow5 already closed 331s 21-Jul-24 22:29:32 - [DEBUG]: pathname: examples/example_write_append.blow5 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_yield_reads: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_single_write_time: 0.02851724624633789 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: examples/example2.slow5, mode: r 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 331s 21-Jul-24 22:29:32 - [DEBUG]: Number of read_groups: 4 331s 21-Jul-24 22:29:32 - [DEBUG]: pathname: examples/example2.slow5 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_slow5_get_next: 0.022403240203857422 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_yield_reads: 0.02393484115600586 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_single_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_names starting 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_names aux_len: 5 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_types starting 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_types aux_len: 5 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() ret: 153015 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() ret: 76423 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() ret: 153015 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() ret: 76423 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() ret: 153015 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() ret: 76423 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() ret: 153049 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_write() ret: 76457 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: slow5_rec_free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record: function complete, returning 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: -1 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 331s 21-Jul-24 22:29:32 - [DEBUG]: examples/example2.slow5 closed 331s 21-Jul-24 22:29:32 - [DEBUG]: examples/example_write_append_aux.blow5 closed 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: examples/example2.slow5, mode: r 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 331s 21-Jul-24 22:29:32 - [DEBUG]: Number of read_groups: 4 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next_multi return: 3 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_names starting 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_names aux_len: 5 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_types starting 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_types aux_len: 5 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next_multi return: 3 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next_multi return: 2 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next_multi has no more batches - batchsize:3 ret:2 331s 21-Jul-24 22:29:32 - [DEBUG]: seq_reads_multi timings: 331s 21-Jul-24 22:29:32 - [DEBUG]: aux_total_time: 0.0002911090850830078 331s 21-Jul-24 22:29:32 - [DEBUG]: primary_total_time: 0.0002536773681640625 331s 21-Jul-24 22:29:32 - [DEBUG]: pA_total_time: 0.00749516487121582 331s 21-Jul-24 22:29:32 - [DEBUG]: signal_total_time: 0.0002319812774658203 331s 21-Jul-24 22:29:32 - [DEBUG]: examples/example2.slow5 closed 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: examples/example2.slow5, mode: r 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 331s 21-Jul-24 22:29:32 - [DEBUG]: Number of read_groups: 4 331s 21-Jul-24 22:29:32 - [DEBUG]: pathname: examples/example2.slow5 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_slow5_get_next: 0.018857240676879883 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_yield_reads: 0.008077144622802734 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_single_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: examples/example2.slow5, mode: r 331s 21-Jul-24 22:29:32 - [DEBUG]: Creating/loading index... 331s 21-Jul-24 22:29:32 - [DEBUG]: Setting up batching... 331s 21-Jul-24 22:29:32 - [DEBUG]: read_list: ['r0', 'r1', 'r2', 'r3', 'r4', 'r5', '0a238451-b9ed-446d-a152-badd074006c4', '0d624d4b-671f-40b8-9798-84f2ccc4d7fc'] 331s 21-Jul-24 22:29:32 - [DEBUG]: batch for loop start 331s 21-Jul-24 22:29:32 - [DEBUG]: Batch: r0,r1,r2 331s 21-Jul-24 22:29:32 - [DEBUG]: Starting rid assignment 331s 21-Jul-24 22:29:32 - [DEBUG]: readID: r0, bin: b'r0' 331s 21-Jul-24 22:29:32 - [DEBUG]: readID: r1, bin: b'r1' 331s 21-Jul-24 22:29:32 - [DEBUG]: readID: r2, bin: b'r2' 331s 21-Jul-24 22:29:32 - [DEBUG]: rid assignment complete 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_batch: num_reads: 3 331s 21-Jul-24 22:29:32 - [DEBUG]: get_read_multi slow5_get_batch ret: 3 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_names starting 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_names aux_len: 5 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_types starting 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_types aux_len: 5 331s 21-Jul-24 22:29:32 - [DEBUG]: Batch: r3,r4,r5 331s 21-Jul-24 22:29:32 - [DEBUG]: Starting rid assignment 331s 21-Jul-24 22:29:32 - [DEBUG]: readID: r3, bin: b'r3' 331s 21-Jul-24 22:29:32 - [DEBUG]: readID: r4, bin: b'r4' 331s 21-Jul-24 22:29:32 - [DEBUG]: readID: r5, bin: b'r5' 331s 21-Jul-24 22:29:32 - [DEBUG]: rid assignment complete 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_batch: num_reads: 3 331s 21-Jul-24 22:29:32 - [DEBUG]: get_read_multi slow5_get_batch ret: 3 331s 21-Jul-24 22:29:32 - [DEBUG]: Batch: 0a238451-b9ed-446d-a152-badd074006c4,0d624d4b-671f-40b8-9798-84f2ccc4d7fc 331s 21-Jul-24 22:29:32 - [DEBUG]: Starting rid assignment 331s 21-Jul-24 22:29:32 - [DEBUG]: readID: 0a238451-b9ed-446d-a152-badd074006c4, bin: b'0a238451-b9ed-446d-a152-badd074006c4' 331s 21-Jul-24 22:29:32 - [DEBUG]: readID: 0d624d4b-671f-40b8-9798-84f2ccc4d7fc, bin: b'0d624d4b-671f-40b8-9798-84f2ccc4d7fc' 331s 21-Jul-24 22:29:32 - [DEBUG]: rid assignment complete 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_batch: num_reads: 2 331s 21-Jul-24 22:29:32 - [DEBUG]: get_read_multi slow5_get_batch ret: 2 331s 21-Jul-24 22:29:32 - [DEBUG]: seq_reads_multi timings: 331s 21-Jul-24 22:29:32 - [DEBUG]: examples/example2.slow5 closed 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: examples/example_write_aux_multi.slow5, mode: w 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: b'examples/example_write_aux_multi.slow5', mode: b'w' 331s 21-Jul-24 22:29:32 - [DEBUG]: Not writing blow5, skipping compression steps 331s 21-Jul-24 22:29:32 - [DEBUG]: examples/example_write_append_aux.blow5 already closed 331s 21-Jul-24 22:29:32 - [DEBUG]: pathname: examples/example_write_append_aux.blow5 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_yield_reads: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_single_write_time: 0.02870035171508789 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: examples/example2.slow5, mode: r 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 331s 21-Jul-24 22:29:32 - [DEBUG]: Number of read_groups: 4 331s 21-Jul-24 22:29:32 - [DEBUG]: pathname: examples/example2.slow5 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_slow5_get_next: 0.022367477416992188 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_yield_reads: 0.023855924606323242 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_single_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_names starting 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_names aux_len: 5 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_types starting 331s 21-Jul-24 22:29:32 - [DEBUG]: get_aux_types aux_len: 5 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: 0 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next return: -1 331s 21-Jul-24 22:29:32 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: Setting up batching... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: batch for loop start 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checking header stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: writting header... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: header written 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_write_batch() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: free() aux 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_write_batch() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: free() aux 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: _record_type_validation running 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: doing aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux passed tests... 331s 21-Jul-24 22:29:32 - [DEBUG]: _record_type_validation: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: _record_type_validation done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_rec_init() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write assignments done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write processing raw_signal 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: self.write raw_signal done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: aux stuff done 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: slow5_write_batch() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: free() 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: free() aux 331s 21-Jul-24 22:29:32 - [DEBUG]: write_record_batch: function complete, returning 0 331s 21-Jul-24 22:29:32 - [DEBUG]: examples/example2.slow5 closed 331s 21-Jul-24 22:29:32 - [DEBUG]: examples/example_write_aux_multi.slow5 closed 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: examples/example2.slow5, mode: r 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 331s 21-Jul-24 22:29:32 - [DEBUG]: Number of read_groups: 4 331s 21-Jul-24 22:29:32 - [DEBUG]: pathname: examples/example2.slow5 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_slow5_get_next: 0.022498130798339844 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_yield_reads: 0.023967504501342773 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_single_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: FILE: examples/example2.slow5, mode: r 331s 21-Jul-24 22:29:32 - [DEBUG]: Creating/loading index... 331s 21-Jul-24 22:29:32 - [DEBUG]: examples/example2.slow5 closed 331s {'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'} 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ============================================== 331s write reads with aux 331s ret: write_header(): 0 331s ret: write_header(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ============================================== 331s append reads with aux 331s ret: write_header(): 0 331s ret: write_header(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ret: write_record(): 0 331s ============================================== 331s seq_reads_multi with aux: 331s type check reads: 331s r0 331s read_number 4019 331s r1 331s read_number 2287 331s r2 331s read_number 4019 331s r3 331s read_number 2287 331s r4 331s read_number 4019 331s r5 331s read_number 2287 331s 0a238451-b9ed-446d-a152-badd074006c4 331s read_number 4019 331s 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 331s read_number 2287 331s ============================================== 331s get_reads_multi with aux: 331s type check reads: 331s r0 331s read_number 4019 331s r1 331s read_number 2287 331s r2 331s read_number 4019 331s r3 331s read_number 2287 331s r4 331s read_number 4019 331s r5 331s read_number 2287 331s 0a238451-b9ed-446d-a152-badd074006c4 331s read_number 4019 331s 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 331s read_number 2287 331s ============================================== 331s write reads with aux multi 331s ret: write_header(): 0 331s ret: write_header(): 0 331s {'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)}} 331s {'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}} 331s ret: write_record(): 0 331s ============================================== 331s get all readIDs from index 331s ['r0', 'r1', 'r2', 'r3', 'r4', 'r5', '0a238451-b9ed-446d-a152-badd074006c4', '0d624d4b-671f-40b8-9798-84f2ccc4d7fc'] 331s number of reads: 8 331s ============================================== 331s done 331s 21-Jul-24 22:29:32 - [DEBUG]: pathname: examples/example.slow5 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_slow5_get_next: 0.01478886604309082 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_yield_reads: 0.015543699264526367 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_single_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: pathname: examples/example2.slow5 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_slow5_get_next: 0.02284693717956543 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_yield_reads: 0.036763668060302734 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_single_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: examples/example_write_aux_multi.slow5 already closed 331s 21-Jul-24 22:29:32 - [DEBUG]: pathname: examples/example_write_aux_multi.slow5 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_yield_reads: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_single_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_signal_time: 0.030772924423217773 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_time: 0.06672787666320801 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: pathname: examples/example2.slow5 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_yield_reads: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_single_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: examples/example_write_append_aux.blow5 already closed 331s 21-Jul-24 22:29:32 - [DEBUG]: pathname: examples/example_write_append_aux.blow5 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_yield_reads: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_single_write_time: 0.028792142868041992 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: pathname: examples/example2.slow5 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_time_yield_reads: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_single_write_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 331s 21-Jul-24 22:29:32 - [DEBUG]: total_multi_write_time: 0.0 seconds 331s autopkgtest [22:29:32]: test run-pybinding-test: -----------------------] 337s autopkgtest [22:29:38]: test run-pybinding-test: - - - - - - - - - - results - - - - - - - - - - 337s run-pybinding-test PASS 341s autopkgtest [22:29:42]: test run-pkg-test: preparing testbed 420s autopkgtest [22:31:01]: testbed dpkg architecture: armhf 423s autopkgtest [22:31:04]: testbed apt version: 2.9.6 423s autopkgtest [22:31:04]: @@@@@@@@@@@@@@@@@@@@ test bed setup 433s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 434s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [62.0 kB] 435s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 435s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [393 kB] 435s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3440 B] 435s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main armhf Packages [89.4 kB] 435s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main armhf c-n-f Metadata [1428 B] 435s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted armhf Packages [1368 B] 435s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted armhf c-n-f Metadata [120 B] 435s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe armhf Packages [327 kB] 435s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe armhf c-n-f Metadata [6916 B] 435s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse armhf Packages [2072 B] 435s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse armhf c-n-f Metadata [120 B] 438s Fetched 1021 kB in 2s (454 kB/s) 438s Reading package lists... 457s tee: /proc/self/fd/2: Permission denied 486s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 486s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 486s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 486s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 495s Reading package lists... 495s Reading package lists... 496s Building dependency tree... 496s Reading state information... 496s Calculating upgrade... 497s The following packages will be upgraded: 497s cloud-init gdisk libbpf1 libpython3-stdlib libudisks2-0 libxml2 497s netcat-openbsd python3 python3-gdbm python3-minimal udisks2 497s 11 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 497s Need to get 2072 kB of archives. 497s After this operation, 30.7 kB disk space will be freed. 497s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main armhf python3-minimal armhf 3.12.4-1 [27.1 kB] 497s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main armhf python3 armhf 3.12.4-1 [24.0 kB] 497s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main armhf libpython3-stdlib armhf 3.12.4-1 [9824 B] 497s Get:4 http://ftpmaster.internal/ubuntu oracular/main armhf libbpf1 armhf 1:1.4.5-1 [151 kB] 497s Get:5 http://ftpmaster.internal/ubuntu oracular/main armhf libxml2 armhf 2.12.7+dfsg-3 [560 kB] 497s Get:6 http://ftpmaster.internal/ubuntu oracular/main armhf netcat-openbsd armhf 1.226-1.1 [42.2 kB] 497s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main armhf python3-gdbm armhf 3.12.4-2 [16.9 kB] 497s Get:8 http://ftpmaster.internal/ubuntu oracular/main armhf udisks2 armhf 2.10.1-9ubuntu1 [277 kB] 497s Get:9 http://ftpmaster.internal/ubuntu oracular/main armhf libudisks2-0 armhf 2.10.1-9ubuntu1 [142 kB] 497s Get:10 http://ftpmaster.internal/ubuntu oracular/main armhf cloud-init all 24.3~1g6e4153b3-0ubuntu1 [592 kB] 498s Get:11 http://ftpmaster.internal/ubuntu oracular/main armhf gdisk armhf 1.0.10-2 [229 kB] 502s Preconfiguring packages ... 503s Fetched 2072 kB in 1s (2821 kB/s) 504s (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 ... 58436 files and directories currently installed.) 504s Preparing to unpack .../python3-minimal_3.12.4-1_armhf.deb ... 504s Unpacking python3-minimal (3.12.4-1) over (3.12.3-0ubuntu1) ... 504s Setting up python3-minimal (3.12.4-1) ... 506s (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 ... 58436 files and directories currently installed.) 506s Preparing to unpack .../0-python3_3.12.4-1_armhf.deb ... 506s Unpacking python3 (3.12.4-1) over (3.12.3-0ubuntu1) ... 508s Preparing to unpack .../1-libpython3-stdlib_3.12.4-1_armhf.deb ... 508s Unpacking libpython3-stdlib:armhf (3.12.4-1) over (3.12.3-0ubuntu1) ... 509s Preparing to unpack .../2-libbpf1_1%3a1.4.5-1_armhf.deb ... 509s Unpacking libbpf1:armhf (1:1.4.5-1) over (1:1.4.3-1) ... 510s Preparing to unpack .../3-libxml2_2.12.7+dfsg-3_armhf.deb ... 510s Unpacking libxml2:armhf (2.12.7+dfsg-3) over (2.9.14+dfsg-1.3ubuntu3) ... 511s Preparing to unpack .../4-netcat-openbsd_1.226-1.1_armhf.deb ... 511s Unpacking netcat-openbsd (1.226-1.1) over (1.226-1ubuntu2) ... 512s Preparing to unpack .../5-python3-gdbm_3.12.4-2_armhf.deb ... 512s Unpacking python3-gdbm:armhf (3.12.4-2) over (3.12.3-0ubuntu1) ... 514s Preparing to unpack .../6-udisks2_2.10.1-9ubuntu1_armhf.deb ... 514s Unpacking udisks2 (2.10.1-9ubuntu1) over (2.10.1-9) ... 515s Preparing to unpack .../7-libudisks2-0_2.10.1-9ubuntu1_armhf.deb ... 515s Unpacking libudisks2-0:armhf (2.10.1-9ubuntu1) over (2.10.1-9) ... 516s Preparing to unpack .../8-cloud-init_24.3~1g6e4153b3-0ubuntu1_all.deb ... 518s Unpacking cloud-init (24.3~1g6e4153b3-0ubuntu1) over (24.2-0ubuntu1) ... 520s Preparing to unpack .../9-gdisk_1.0.10-2_armhf.deb ... 520s Unpacking gdisk (1.0.10-2) over (1.0.10-1build1) ... 520s Setting up netcat-openbsd (1.226-1.1) ... 520s Setting up gdisk (1.0.10-2) ... 520s Setting up libxml2:armhf (2.12.7+dfsg-3) ... 520s Setting up libbpf1:armhf (1:1.4.5-1) ... 520s Setting up libudisks2-0:armhf (2.10.1-9ubuntu1) ... 520s Setting up libpython3-stdlib:armhf (3.12.4-1) ... 520s Setting up udisks2 (2.10.1-9ubuntu1) ... 520s vda: Failed to write 'change' to '/sys/devices/pci0000:00/0000:00:01.3/0000:04:00.0/virtio2/block/vda/uevent': Permission denied 520s vda1: Failed to write 'change' to '/sys/devices/pci0000:00/0000:00:01.3/0000:04:00.0/virtio2/block/vda/vda1/uevent': Permission denied 520s vda15: Failed to write 'change' to '/sys/devices/pci0000:00/0000:00:01.3/0000:04:00.0/virtio2/block/vda/vda15/uevent': Permission denied 520s vda2: Failed to write 'change' to '/sys/devices/pci0000:00/0000:00:01.3/0000:04:00.0/virtio2/block/vda/vda2/uevent': Permission denied 520s loop0: Failed to write 'change' to '/sys/devices/virtual/block/loop0/uevent': Permission denied 520s loop1: Failed to write 'change' to '/sys/devices/virtual/block/loop1/uevent': Permission denied 520s loop2: Failed to write 'change' to '/sys/devices/virtual/block/loop2/uevent': Permission denied 520s loop3: Failed to write 'change' to '/sys/devices/virtual/block/loop3/uevent': Permission denied 520s loop4: Failed to write 'change' to '/sys/devices/virtual/block/loop4/uevent': Permission denied 520s loop5: Failed to write 'change' to '/sys/devices/virtual/block/loop5/uevent': Permission denied 520s loop6: Failed to write 'change' to '/sys/devices/virtual/block/loop6/uevent': Permission denied 520s loop7: Failed to write 'change' to '/sys/devices/virtual/block/loop7/uevent': Permission denied 522s Setting up python3 (3.12.4-1) ... 522s Setting up cloud-init (24.3~1g6e4153b3-0ubuntu1) ... 525s Setting up python3-gdbm:armhf (3.12.4-2) ... 525s Processing triggers for rsyslog (8.2312.0-3ubuntu9) ... 526s Processing triggers for man-db (2.12.1-2) ... 527s Processing triggers for dbus (1.14.10-4ubuntu4) ... 527s Processing triggers for libc-bin (2.39-0ubuntu9) ... 528s Reading package lists... 528s Building dependency tree... 528s Reading state information... 530s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 532s autopkgtest [22:32:53]: rebooting testbed after setup commands that affected boot 645s Reading package lists... 645s Building dependency tree... 645s Reading state information... 646s Starting pkgProblemResolver with broken count: 0 646s Starting 2 pkgProblemResolver with broken count: 0 646s Done 646s The following additional packages will be installed: 646s build-essential cpp cpp-13 cpp-13-arm-linux-gnueabihf 646s cpp-arm-linux-gnueabihf g++ g++-13 g++-13-arm-linux-gnueabihf 646s g++-arm-linux-gnueabihf gcc gcc-13 gcc-13-arm-linux-gnueabihf gcc-13-base 646s gcc-arm-linux-gnueabihf libasan8 libatomic1 libblas3 libc-dev-bin libc6-dev 646s libcc1-0 libcrypt-dev libgcc-13-dev libgfortran5 libgomp1 libisl23 646s liblapack3 libmpc3 libslow5-0t64 libslow5-dev libstdc++-13-dev 646s libstreamvbyte-dev libstreamvbyte0 libubsan1 linux-libc-dev python3-numpy 646s python3-slow5 rpcsvc-proto zlib1g-dev 646s Suggested packages: 646s cpp-doc gcc-13-locales cpp-13-doc gcc-13-doc gcc-multilib manpages-dev 646s autoconf automake libtool flex bison gdb gcc-doc gdb-arm-linux-gnueabihf 646s glibc-doc libstdc++-13-doc gfortran python-numpy-doc python3-dev 646s python3-pytest 646s Recommended packages: 646s manpages manpages-dev libc-devtools 646s The following NEW packages will be installed: 646s autopkgtest-satdep build-essential cpp cpp-13 cpp-13-arm-linux-gnueabihf 646s cpp-arm-linux-gnueabihf g++ g++-13 g++-13-arm-linux-gnueabihf 646s g++-arm-linux-gnueabihf gcc gcc-13 gcc-13-arm-linux-gnueabihf gcc-13-base 646s gcc-arm-linux-gnueabihf libasan8 libatomic1 libblas3 libc-dev-bin libc6-dev 646s libcc1-0 libcrypt-dev libgcc-13-dev libgfortran5 libgomp1 libisl23 646s liblapack3 libmpc3 libslow5-0t64 libslow5-dev libstdc++-13-dev 646s libstreamvbyte-dev libstreamvbyte0 libubsan1 linux-libc-dev python3-numpy 646s python3-slow5 rpcsvc-proto zlib1g-dev 646s 0 upgraded, 39 newly installed, 0 to remove and 0 not upgraded. 646s Need to get 53.2 MB/53.2 MB of archives. 646s After this operation, 167 MB of additional disk space will be used. 646s Get:1 /tmp/autopkgtest.Jz6Pkd/2-autopkgtest-satdep.deb autopkgtest-satdep armhf 0 [760 B] 647s Get:2 http://ftpmaster.internal/ubuntu oracular/main armhf libc-dev-bin armhf 2.39-0ubuntu9 [19.1 kB] 647s Get:3 http://ftpmaster.internal/ubuntu oracular/main armhf linux-libc-dev armhf 6.8.0-31.31 [1557 kB] 647s Get:4 http://ftpmaster.internal/ubuntu oracular/main armhf libcrypt-dev armhf 1:4.4.36-4build1 [120 kB] 647s Get:5 http://ftpmaster.internal/ubuntu oracular/main armhf rpcsvc-proto armhf 1.4.2-0ubuntu7 [62.2 kB] 647s Get:6 http://ftpmaster.internal/ubuntu oracular/main armhf libc6-dev armhf 2.39-0ubuntu9 [1351 kB] 647s Get:7 http://ftpmaster.internal/ubuntu oracular/main armhf gcc-13-base armhf 13.3.0-3ubuntu1 [50.8 kB] 647s Get:8 http://ftpmaster.internal/ubuntu oracular/main armhf libisl23 armhf 0.26-3build1 [544 kB] 647s Get:9 http://ftpmaster.internal/ubuntu oracular/main armhf libmpc3 armhf 1.3.1-1build1 [46.7 kB] 647s Get:10 http://ftpmaster.internal/ubuntu oracular/main armhf cpp-13-arm-linux-gnueabihf armhf 13.3.0-3ubuntu1 [8248 kB] 647s Get:11 http://ftpmaster.internal/ubuntu oracular/main armhf cpp-13 armhf 13.3.0-3ubuntu1 [1034 B] 647s Get:12 http://ftpmaster.internal/ubuntu oracular/main armhf cpp-arm-linux-gnueabihf armhf 4:13.3.0-2ubuntu2 [5410 B] 647s Get:13 http://ftpmaster.internal/ubuntu oracular/main armhf cpp armhf 4:13.3.0-2ubuntu2 [22.5 kB] 647s Get:14 http://ftpmaster.internal/ubuntu oracular/main armhf libcc1-0 armhf 14.1.0-4ubuntu2 [43.3 kB] 647s Get:15 http://ftpmaster.internal/ubuntu oracular/main armhf libgomp1 armhf 14.1.0-4ubuntu2 [125 kB] 647s Get:16 http://ftpmaster.internal/ubuntu oracular/main armhf libatomic1 armhf 14.1.0-4ubuntu2 [7846 B] 647s Get:17 http://ftpmaster.internal/ubuntu oracular/main armhf libasan8 armhf 14.1.0-4ubuntu2 [2901 kB] 647s Get:18 http://ftpmaster.internal/ubuntu oracular/main armhf libubsan1 armhf 14.1.0-4ubuntu2 [1149 kB] 647s Get:19 http://ftpmaster.internal/ubuntu oracular/main armhf libgcc-13-dev armhf 13.3.0-3ubuntu1 [897 kB] 647s Get:20 http://ftpmaster.internal/ubuntu oracular/main armhf gcc-13-arm-linux-gnueabihf armhf 13.3.0-3ubuntu1 [16.1 MB] 648s Get:21 http://ftpmaster.internal/ubuntu oracular/main armhf gcc-13 armhf 13.3.0-3ubuntu1 [462 kB] 648s Get:22 http://ftpmaster.internal/ubuntu oracular/main armhf gcc-arm-linux-gnueabihf armhf 4:13.3.0-2ubuntu2 [1216 B] 648s Get:23 http://ftpmaster.internal/ubuntu oracular/main armhf gcc armhf 4:13.3.0-2ubuntu2 [5016 B] 648s Get:24 http://ftpmaster.internal/ubuntu oracular/main armhf libstdc++-13-dev armhf 13.3.0-3ubuntu1 [2505 kB] 648s Get:25 http://ftpmaster.internal/ubuntu oracular/main armhf g++-13-arm-linux-gnueabihf armhf 13.3.0-3ubuntu1 [9427 kB] 648s Get:26 http://ftpmaster.internal/ubuntu oracular/main armhf g++-13 armhf 13.3.0-3ubuntu1 [16.0 kB] 648s Get:27 http://ftpmaster.internal/ubuntu oracular/main armhf g++-arm-linux-gnueabihf armhf 4:13.3.0-2ubuntu2 [968 B] 648s Get:28 http://ftpmaster.internal/ubuntu oracular/main armhf g++ armhf 4:13.3.0-2ubuntu2 [1086 B] 648s Get:29 http://ftpmaster.internal/ubuntu oracular/main armhf build-essential armhf 12.10ubuntu1 [4928 B] 648s Get:30 http://ftpmaster.internal/ubuntu oracular/main armhf libblas3 armhf 3.12.0-3build1 [123 kB] 648s Get:31 http://ftpmaster.internal/ubuntu oracular/main armhf libgfortran5 armhf 14.1.0-4ubuntu2 [311 kB] 648s Get:32 http://ftpmaster.internal/ubuntu oracular/main armhf liblapack3 armhf 3.12.0-3build1 [2085 kB] 648s Get:33 http://ftpmaster.internal/ubuntu oracular/universe armhf libslow5-0t64 armhf 0.7.0+dfsg-2.1build1 [63.0 kB] 648s Get:34 http://ftpmaster.internal/ubuntu oracular/universe armhf libslow5-dev armhf 0.7.0+dfsg-2.1build1 [84.4 kB] 648s Get:35 http://ftpmaster.internal/ubuntu oracular/universe armhf libstreamvbyte0 armhf 0.4.1-4ubuntu1 [5742 B] 648s Get:36 http://ftpmaster.internal/ubuntu oracular/universe armhf libstreamvbyte-dev armhf 0.4.1-4ubuntu1 [6178 B] 648s Get:37 http://ftpmaster.internal/ubuntu oracular/main armhf python3-numpy armhf 1:1.26.4+ds-10 [3541 kB] 648s Get:38 http://ftpmaster.internal/ubuntu oracular/universe armhf python3-slow5 armhf 0.7.0+dfsg-2.1build1 [460 kB] 648s Get:39 http://ftpmaster.internal/ubuntu oracular/main armhf zlib1g-dev armhf 1:1.3.dfsg-3.1ubuntu2 [880 kB] 649s Fetched 53.2 MB in 2s (27.8 MB/s) 649s Selecting previously unselected package libc-dev-bin. 649s (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 ... 58440 files and directories currently installed.) 649s Preparing to unpack .../00-libc-dev-bin_2.39-0ubuntu9_armhf.deb ... 649s Unpacking libc-dev-bin (2.39-0ubuntu9) ... 649s Selecting previously unselected package linux-libc-dev:armhf. 649s Preparing to unpack .../01-linux-libc-dev_6.8.0-31.31_armhf.deb ... 649s Unpacking linux-libc-dev:armhf (6.8.0-31.31) ... 649s Selecting previously unselected package libcrypt-dev:armhf. 649s Preparing to unpack .../02-libcrypt-dev_1%3a4.4.36-4build1_armhf.deb ... 649s Unpacking libcrypt-dev:armhf (1:4.4.36-4build1) ... 649s Selecting previously unselected package rpcsvc-proto. 649s Preparing to unpack .../03-rpcsvc-proto_1.4.2-0ubuntu7_armhf.deb ... 649s Unpacking rpcsvc-proto (1.4.2-0ubuntu7) ... 649s Selecting previously unselected package libc6-dev:armhf. 649s Preparing to unpack .../04-libc6-dev_2.39-0ubuntu9_armhf.deb ... 649s Unpacking libc6-dev:armhf (2.39-0ubuntu9) ... 649s Selecting previously unselected package gcc-13-base:armhf. 649s Preparing to unpack .../05-gcc-13-base_13.3.0-3ubuntu1_armhf.deb ... 649s Unpacking gcc-13-base:armhf (13.3.0-3ubuntu1) ... 649s Selecting previously unselected package libisl23:armhf. 649s Preparing to unpack .../06-libisl23_0.26-3build1_armhf.deb ... 649s Unpacking libisl23:armhf (0.26-3build1) ... 649s Selecting previously unselected package libmpc3:armhf. 649s Preparing to unpack .../07-libmpc3_1.3.1-1build1_armhf.deb ... 649s Unpacking libmpc3:armhf (1.3.1-1build1) ... 649s Selecting previously unselected package cpp-13-arm-linux-gnueabihf. 649s Preparing to unpack .../08-cpp-13-arm-linux-gnueabihf_13.3.0-3ubuntu1_armhf.deb ... 649s Unpacking cpp-13-arm-linux-gnueabihf (13.3.0-3ubuntu1) ... 650s Selecting previously unselected package cpp-13. 650s Preparing to unpack .../09-cpp-13_13.3.0-3ubuntu1_armhf.deb ... 650s Unpacking cpp-13 (13.3.0-3ubuntu1) ... 650s Selecting previously unselected package cpp-arm-linux-gnueabihf. 650s Preparing to unpack .../10-cpp-arm-linux-gnueabihf_4%3a13.3.0-2ubuntu2_armhf.deb ... 650s Unpacking cpp-arm-linux-gnueabihf (4:13.3.0-2ubuntu2) ... 650s Selecting previously unselected package cpp. 650s Preparing to unpack .../11-cpp_4%3a13.3.0-2ubuntu2_armhf.deb ... 650s Unpacking cpp (4:13.3.0-2ubuntu2) ... 650s Selecting previously unselected package libcc1-0:armhf. 650s Preparing to unpack .../12-libcc1-0_14.1.0-4ubuntu2_armhf.deb ... 650s Unpacking libcc1-0:armhf (14.1.0-4ubuntu2) ... 650s Selecting previously unselected package libgomp1:armhf. 650s Preparing to unpack .../13-libgomp1_14.1.0-4ubuntu2_armhf.deb ... 650s Unpacking libgomp1:armhf (14.1.0-4ubuntu2) ... 650s Selecting previously unselected package libatomic1:armhf. 650s Preparing to unpack .../14-libatomic1_14.1.0-4ubuntu2_armhf.deb ... 650s Unpacking libatomic1:armhf (14.1.0-4ubuntu2) ... 650s Selecting previously unselected package libasan8:armhf. 650s Preparing to unpack .../15-libasan8_14.1.0-4ubuntu2_armhf.deb ... 650s Unpacking libasan8:armhf (14.1.0-4ubuntu2) ... 650s Selecting previously unselected package libubsan1:armhf. 650s Preparing to unpack .../16-libubsan1_14.1.0-4ubuntu2_armhf.deb ... 650s Unpacking libubsan1:armhf (14.1.0-4ubuntu2) ... 650s Selecting previously unselected package libgcc-13-dev:armhf. 650s Preparing to unpack .../17-libgcc-13-dev_13.3.0-3ubuntu1_armhf.deb ... 650s Unpacking libgcc-13-dev:armhf (13.3.0-3ubuntu1) ... 651s Selecting previously unselected package gcc-13-arm-linux-gnueabihf. 651s Preparing to unpack .../18-gcc-13-arm-linux-gnueabihf_13.3.0-3ubuntu1_armhf.deb ... 651s Unpacking gcc-13-arm-linux-gnueabihf (13.3.0-3ubuntu1) ... 651s Selecting previously unselected package gcc-13. 651s Preparing to unpack .../19-gcc-13_13.3.0-3ubuntu1_armhf.deb ... 651s Unpacking gcc-13 (13.3.0-3ubuntu1) ... 651s Selecting previously unselected package gcc-arm-linux-gnueabihf. 651s Preparing to unpack .../20-gcc-arm-linux-gnueabihf_4%3a13.3.0-2ubuntu2_armhf.deb ... 651s Unpacking gcc-arm-linux-gnueabihf (4:13.3.0-2ubuntu2) ... 651s Selecting previously unselected package gcc. 651s Preparing to unpack .../21-gcc_4%3a13.3.0-2ubuntu2_armhf.deb ... 651s Unpacking gcc (4:13.3.0-2ubuntu2) ... 651s Selecting previously unselected package libstdc++-13-dev:armhf. 651s Preparing to unpack .../22-libstdc++-13-dev_13.3.0-3ubuntu1_armhf.deb ... 651s Unpacking libstdc++-13-dev:armhf (13.3.0-3ubuntu1) ... 651s Selecting previously unselected package g++-13-arm-linux-gnueabihf. 651s Preparing to unpack .../23-g++-13-arm-linux-gnueabihf_13.3.0-3ubuntu1_armhf.deb ... 651s Unpacking g++-13-arm-linux-gnueabihf (13.3.0-3ubuntu1) ... 652s Selecting previously unselected package g++-13. 652s Preparing to unpack .../24-g++-13_13.3.0-3ubuntu1_armhf.deb ... 652s Unpacking g++-13 (13.3.0-3ubuntu1) ... 652s Selecting previously unselected package g++-arm-linux-gnueabihf. 652s Preparing to unpack .../25-g++-arm-linux-gnueabihf_4%3a13.3.0-2ubuntu2_armhf.deb ... 652s Unpacking g++-arm-linux-gnueabihf (4:13.3.0-2ubuntu2) ... 652s Selecting previously unselected package g++. 652s Preparing to unpack .../26-g++_4%3a13.3.0-2ubuntu2_armhf.deb ... 652s Unpacking g++ (4:13.3.0-2ubuntu2) ... 652s Selecting previously unselected package build-essential. 652s Preparing to unpack .../27-build-essential_12.10ubuntu1_armhf.deb ... 652s Unpacking build-essential (12.10ubuntu1) ... 652s Selecting previously unselected package libblas3:armhf. 652s Preparing to unpack .../28-libblas3_3.12.0-3build1_armhf.deb ... 652s Unpacking libblas3:armhf (3.12.0-3build1) ... 652s Selecting previously unselected package libgfortran5:armhf. 652s Preparing to unpack .../29-libgfortran5_14.1.0-4ubuntu2_armhf.deb ... 652s Unpacking libgfortran5:armhf (14.1.0-4ubuntu2) ... 652s Selecting previously unselected package liblapack3:armhf. 652s Preparing to unpack .../30-liblapack3_3.12.0-3build1_armhf.deb ... 652s Unpacking liblapack3:armhf (3.12.0-3build1) ... 652s Selecting previously unselected package libslow5-0t64:armhf. 652s Preparing to unpack .../31-libslow5-0t64_0.7.0+dfsg-2.1build1_armhf.deb ... 652s Unpacking libslow5-0t64:armhf (0.7.0+dfsg-2.1build1) ... 652s Selecting previously unselected package libslow5-dev:armhf. 652s Preparing to unpack .../32-libslow5-dev_0.7.0+dfsg-2.1build1_armhf.deb ... 652s Unpacking libslow5-dev:armhf (0.7.0+dfsg-2.1build1) ... 652s Selecting previously unselected package libstreamvbyte0:armhf. 652s Preparing to unpack .../33-libstreamvbyte0_0.4.1-4ubuntu1_armhf.deb ... 652s Unpacking libstreamvbyte0:armhf (0.4.1-4ubuntu1) ... 652s Selecting previously unselected package libstreamvbyte-dev:armhf. 652s Preparing to unpack .../34-libstreamvbyte-dev_0.4.1-4ubuntu1_armhf.deb ... 652s Unpacking libstreamvbyte-dev:armhf (0.4.1-4ubuntu1) ... 653s Selecting previously unselected package python3-numpy. 653s Preparing to unpack .../35-python3-numpy_1%3a1.26.4+ds-10_armhf.deb ... 653s Unpacking python3-numpy (1:1.26.4+ds-10) ... 653s Selecting previously unselected package python3-slow5. 653s Preparing to unpack .../36-python3-slow5_0.7.0+dfsg-2.1build1_armhf.deb ... 653s Unpacking python3-slow5 (0.7.0+dfsg-2.1build1) ... 653s Selecting previously unselected package zlib1g-dev:armhf. 653s Preparing to unpack .../37-zlib1g-dev_1%3a1.3.dfsg-3.1ubuntu2_armhf.deb ... 653s Unpacking zlib1g-dev:armhf (1:1.3.dfsg-3.1ubuntu2) ... 653s Selecting previously unselected package autopkgtest-satdep. 653s Preparing to unpack .../38-2-autopkgtest-satdep.deb ... 653s Unpacking autopkgtest-satdep (0) ... 653s Setting up libstreamvbyte0:armhf (0.4.1-4ubuntu1) ... 653s Setting up linux-libc-dev:armhf (6.8.0-31.31) ... 653s Setting up libgomp1:armhf (14.1.0-4ubuntu2) ... 653s Setting up libblas3:armhf (3.12.0-3build1) ... 653s update-alternatives: using /usr/lib/arm-linux-gnueabihf/blas/libblas.so.3 to provide /usr/lib/arm-linux-gnueabihf/libblas.so.3 (libblas.so.3-arm-linux-gnueabihf) in auto mode 653s Setting up rpcsvc-proto (1.4.2-0ubuntu7) ... 653s Setting up gcc-13-base:armhf (13.3.0-3ubuntu1) ... 653s Setting up libstreamvbyte-dev:armhf (0.4.1-4ubuntu1) ... 653s Setting up libmpc3:armhf (1.3.1-1build1) ... 653s Setting up libatomic1:armhf (14.1.0-4ubuntu2) ... 653s Setting up libslow5-0t64:armhf (0.7.0+dfsg-2.1build1) ... 653s Setting up libgfortran5:armhf (14.1.0-4ubuntu2) ... 653s Setting up libubsan1:armhf (14.1.0-4ubuntu2) ... 653s Setting up libcrypt-dev:armhf (1:4.4.36-4build1) ... 653s Setting up libasan8:armhf (14.1.0-4ubuntu2) ... 653s Setting up libisl23:armhf (0.26-3build1) ... 653s Setting up libc-dev-bin (2.39-0ubuntu9) ... 653s Setting up libcc1-0:armhf (14.1.0-4ubuntu2) ... 653s Setting up liblapack3:armhf (3.12.0-3build1) ... 653s update-alternatives: using /usr/lib/arm-linux-gnueabihf/lapack/liblapack.so.3 to provide /usr/lib/arm-linux-gnueabihf/liblapack.so.3 (liblapack.so.3-arm-linux-gnueabihf) in auto mode 653s Setting up cpp-13-arm-linux-gnueabihf (13.3.0-3ubuntu1) ... 653s Setting up libslow5-dev:armhf (0.7.0+dfsg-2.1build1) ... 653s Setting up python3-numpy (1:1.26.4+ds-10) ... 655s Setting up libgcc-13-dev:armhf (13.3.0-3ubuntu1) ... 655s Setting up libc6-dev:armhf (2.39-0ubuntu9) ... 655s Setting up cpp-arm-linux-gnueabihf (4:13.3.0-2ubuntu2) ... 655s Setting up libstdc++-13-dev:armhf (13.3.0-3ubuntu1) ... 655s Setting up cpp-13 (13.3.0-3ubuntu1) ... 655s Setting up gcc-13-arm-linux-gnueabihf (13.3.0-3ubuntu1) ... 655s Setting up gcc-13 (13.3.0-3ubuntu1) ... 655s Setting up python3-slow5 (0.7.0+dfsg-2.1build1) ... 655s Setting up zlib1g-dev:armhf (1:1.3.dfsg-3.1ubuntu2) ... 655s Setting up cpp (4:13.3.0-2ubuntu2) ... 655s Setting up gcc-arm-linux-gnueabihf (4:13.3.0-2ubuntu2) ... 655s Setting up g++-13-arm-linux-gnueabihf (13.3.0-3ubuntu1) ... 655s Setting up g++-arm-linux-gnueabihf (4:13.3.0-2ubuntu2) ... 655s Setting up g++-13 (13.3.0-3ubuntu1) ... 655s Setting up gcc (4:13.3.0-2ubuntu2) ... 655s Setting up g++ (4:13.3.0-2ubuntu2) ... 655s update-alternatives: using /usr/bin/g++ to provide /usr/bin/c++ (c++) in auto mode 655s Setting up build-essential (12.10ubuntu1) ... 655s Setting up autopkgtest-satdep (0) ... 655s Processing triggers for man-db (2.12.1-2) ... 656s Processing triggers for libc-bin (2.39-0ubuntu9) ... 684s (Reading database ... 62120 files and directories currently installed.) 684s Removing autopkgtest-satdep (0) ... 698s autopkgtest [22:35:39]: test run-pkg-test: [----------------------- 700s Checking unit_test_ascii.c 700s Done! 700s Checking unit_test_binary.c 701s Done! 701s Checking unit_test_empty.c 701s Done! 701s Checking unit_test_enum.c 701s Done! 701s Checking unit_test_helpers.c 701s Done! 701s Checking unit_test_lossless.c 701s Done! 701s Checking unit_test_press.c 701s Done! 701s Checking unit_test_two_rg.c 701s Done! 702s autopkgtest [22:35:43]: test run-pkg-test: -----------------------] 706s autopkgtest [22:35:47]: test run-pkg-test: - - - - - - - - - - results - - - - - - - - - - 706s run-pkg-test PASS 710s autopkgtest [22:35:51]: @@@@@@@@@@@@@@@@@@@@ summary 710s run-pybinding-test PASS 710s run-pkg-test PASS