0s autopkgtest [23:50:12]: starting date and time: 2024-07-20 23:50:12+0000 0s autopkgtest [23:50:12]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [23:50:12]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.vg1rz2r_/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:python3-defaults,src:python3-stdlib-extensions --apt-upgrade libslow5lib --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=python3-defaults/3.12.4-1 python3-stdlib-extensions/3.12.4-2' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos01-ppc64el-17.secgroup --name adt-oracular-ppc64el-libslow5lib-20240720-235011-juju-7f2275-prod-proposed-migration-environment-3-87aca0d3-9918-412f-b1e3-501620903c01 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://us.ports.ubuntu.com/ubuntu-ports/ 179s autopkgtest [23:53:11]: testbed dpkg architecture: ppc64el 179s autopkgtest [23:53:11]: testbed apt version: 2.9.6 179s autopkgtest [23:53:11]: @@@@@@@@@@@@@@@@@@@@ test bed setup 190s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 190s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [396 kB] 190s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [62.2 kB] 190s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 190s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4092 B] 190s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [109 kB] 190s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2116 B] 190s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 190s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 190s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [544 kB] 190s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [8952 B] 190s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1840 B] 190s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 192s Fetched 1265 kB in 1s (1505 kB/s) 192s Reading package lists... 196s Reading package lists... 196s Building dependency tree... 196s Reading state information... 196s Calculating upgrade... 196s The following packages will be upgraded: 196s libbpf1 libpython3-stdlib python3 python3-gdbm python3-minimal 196s 5 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 196s Need to get 298 kB of archives. 196s After this operation, 71.7 kB of additional disk space will be used. 196s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el python3-minimal ppc64el 3.12.4-1 [27.1 kB] 196s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el python3 ppc64el 3.12.4-1 [24.0 kB] 196s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpython3-stdlib ppc64el 3.12.4-1 [9818 B] 196s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el libbpf1 ppc64el 1:1.4.5-1 [218 kB] 196s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el python3-gdbm ppc64el 3.12.4-2 [18.9 kB] 197s Fetched 298 kB in 0s (615 kB/s) 197s (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 ... 72765 files and directories currently installed.) 197s Preparing to unpack .../python3-minimal_3.12.4-1_ppc64el.deb ... 197s Unpacking python3-minimal (3.12.4-1) over (3.12.3-0ubuntu1) ... 197s Setting up python3-minimal (3.12.4-1) ... 197s (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 ... 72765 files and directories currently installed.) 197s Preparing to unpack .../python3_3.12.4-1_ppc64el.deb ... 197s Unpacking python3 (3.12.4-1) over (3.12.3-0ubuntu1) ... 197s Preparing to unpack .../libpython3-stdlib_3.12.4-1_ppc64el.deb ... 197s Unpacking libpython3-stdlib:ppc64el (3.12.4-1) over (3.12.3-0ubuntu1) ... 197s Preparing to unpack .../libbpf1_1%3a1.4.5-1_ppc64el.deb ... 197s Unpacking libbpf1:ppc64el (1:1.4.5-1) over (1:1.4.3-1) ... 197s Preparing to unpack .../python3-gdbm_3.12.4-2_ppc64el.deb ... 197s Unpacking python3-gdbm:ppc64el (3.12.4-2) over (3.12.3-0ubuntu1) ... 197s Setting up libbpf1:ppc64el (1:1.4.5-1) ... 197s Setting up libpython3-stdlib:ppc64el (3.12.4-1) ... 197s Setting up python3 (3.12.4-1) ... 197s Setting up python3-gdbm:ppc64el (3.12.4-2) ... 197s Processing triggers for man-db (2.12.1-2) ... 198s Processing triggers for libc-bin (2.39-0ubuntu9) ... 198s Reading package lists... 198s Building dependency tree... 198s Reading state information... 198s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 199s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 199s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 199s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 199s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 200s Reading package lists... 200s Reading package lists... 200s Building dependency tree... 200s Reading state information... 200s Calculating upgrade... 200s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 200s Reading package lists... 201s Building dependency tree... 201s Reading state information... 201s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 213s autopkgtest [23:53:45]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 213s autopkgtest [23:53:45]: @@@@@@@@@@@@@@@@@@@@ apt-source libslow5lib 217s Get:1 http://ftpmaster.internal/ubuntu oracular/universe libslow5lib 0.7.0+dfsg-2.1build1 (dsc) [2541 B] 217s Get:2 http://ftpmaster.internal/ubuntu oracular/universe libslow5lib 0.7.0+dfsg-2.1build1 (tar) [2014 kB] 217s Get:3 http://ftpmaster.internal/ubuntu oracular/universe libslow5lib 0.7.0+dfsg-2.1build1 (diff) [8280 B] 217s gpgv: Signature made Sun Mar 31 19:37:54 2024 UTC 217s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 217s gpgv: issuer "steve.langasek@ubuntu.com" 217s gpgv: Can't check signature: No public key 217s dpkg-source: warning: cannot verify inline signature for ./libslow5lib_0.7.0+dfsg-2.1build1.dsc: no acceptable signature found 217s autopkgtest [23:53:49]: testing package libslow5lib version 0.7.0+dfsg-2.1build1 218s autopkgtest [23:53:50]: build not needed 220s autopkgtest [23:53:52]: test run-pybinding-test: preparing testbed 238s Reading package lists... 238s Building dependency tree... 238s Reading state information... 238s Starting pkgProblemResolver with broken count: 0 238s Starting 2 pkgProblemResolver with broken count: 0 238s Done 238s The following additional packages will be installed: 238s libblas3 libgfortran5 liblapack3 libslow5-0t64 libslow5-dev libstreamvbyte0 238s python3-all python3-numpy python3-slow5 239s Suggested packages: 239s gcc gfortran python-numpy-doc python3-dev python3-pytest 239s The following NEW packages will be installed: 239s autopkgtest-satdep libblas3 libgfortran5 liblapack3 libslow5-0t64 239s libslow5-dev libstreamvbyte0 python3-all python3-numpy python3-slow5 239s 0 upgraded, 10 newly installed, 0 to remove and 0 not upgraded. 239s Need to get 8670 kB/8671 kB of archives. 239s After this operation, 43.2 MB of additional disk space will be used. 239s Get:1 /tmp/autopkgtest.rFuwGA/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [728 B] 239s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libblas3 ppc64el 3.12.0-3build1 [227 kB] 239s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgfortran5 ppc64el 14.1.0-4ubuntu2 [571 kB] 239s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el liblapack3 ppc64el 3.12.0-3build1 [2804 kB] 239s Get:5 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libslow5-0t64 ppc64el 0.7.0+dfsg-2.1build1 [70.7 kB] 239s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libslow5-dev ppc64el 0.7.0+dfsg-2.1build1 [103 kB] 239s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libstreamvbyte0 ppc64el 0.4.1-4ubuntu1 [6400 B] 239s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el python3-all ppc64el 3.12.4-1 [884 B] 239s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-numpy ppc64el 1:1.26.4+ds-10 [4408 kB] 240s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el python3-slow5 ppc64el 0.7.0+dfsg-2.1build1 [479 kB] 240s Fetched 8670 kB in 1s (6599 kB/s) 240s Selecting previously unselected package libblas3:ppc64el. 240s (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 ... 72768 files and directories currently installed.) 240s Preparing to unpack .../0-libblas3_3.12.0-3build1_ppc64el.deb ... 240s Unpacking libblas3:ppc64el (3.12.0-3build1) ... 240s Selecting previously unselected package libgfortran5:ppc64el. 240s Preparing to unpack .../1-libgfortran5_14.1.0-4ubuntu2_ppc64el.deb ... 240s Unpacking libgfortran5:ppc64el (14.1.0-4ubuntu2) ... 240s Selecting previously unselected package liblapack3:ppc64el. 240s Preparing to unpack .../2-liblapack3_3.12.0-3build1_ppc64el.deb ... 240s Unpacking liblapack3:ppc64el (3.12.0-3build1) ... 240s Selecting previously unselected package libslow5-0t64:ppc64el. 240s Preparing to unpack .../3-libslow5-0t64_0.7.0+dfsg-2.1build1_ppc64el.deb ... 240s Unpacking libslow5-0t64:ppc64el (0.7.0+dfsg-2.1build1) ... 240s Selecting previously unselected package libslow5-dev:ppc64el. 240s Preparing to unpack .../4-libslow5-dev_0.7.0+dfsg-2.1build1_ppc64el.deb ... 240s Unpacking libslow5-dev:ppc64el (0.7.0+dfsg-2.1build1) ... 240s Selecting previously unselected package libstreamvbyte0:ppc64el. 240s Preparing to unpack .../5-libstreamvbyte0_0.4.1-4ubuntu1_ppc64el.deb ... 240s Unpacking libstreamvbyte0:ppc64el (0.4.1-4ubuntu1) ... 240s Selecting previously unselected package python3-all. 240s Preparing to unpack .../6-python3-all_3.12.4-1_ppc64el.deb ... 240s Unpacking python3-all (3.12.4-1) ... 240s Selecting previously unselected package python3-numpy. 240s Preparing to unpack .../7-python3-numpy_1%3a1.26.4+ds-10_ppc64el.deb ... 240s Unpacking python3-numpy (1:1.26.4+ds-10) ... 241s Selecting previously unselected package python3-slow5. 241s Preparing to unpack .../8-python3-slow5_0.7.0+dfsg-2.1build1_ppc64el.deb ... 241s Unpacking python3-slow5 (0.7.0+dfsg-2.1build1) ... 241s Selecting previously unselected package autopkgtest-satdep. 241s Preparing to unpack .../9-1-autopkgtest-satdep.deb ... 241s Unpacking autopkgtest-satdep (0) ... 241s Setting up libstreamvbyte0:ppc64el (0.4.1-4ubuntu1) ... 241s Setting up python3-all (3.12.4-1) ... 241s Setting up libblas3:ppc64el (3.12.0-3build1) ... 241s update-alternatives: using /usr/lib/powerpc64le-linux-gnu/blas/libblas.so.3 to provide /usr/lib/powerpc64le-linux-gnu/libblas.so.3 (libblas.so.3-powerpc64le-linux-gnu) in auto mode 241s Setting up libslow5-0t64:ppc64el (0.7.0+dfsg-2.1build1) ... 241s Setting up libgfortran5:ppc64el (14.1.0-4ubuntu2) ... 241s Setting up liblapack3:ppc64el (3.12.0-3build1) ... 241s update-alternatives: using /usr/lib/powerpc64le-linux-gnu/lapack/liblapack.so.3 to provide /usr/lib/powerpc64le-linux-gnu/liblapack.so.3 (liblapack.so.3-powerpc64le-linux-gnu) in auto mode 241s Setting up libslow5-dev:ppc64el (0.7.0+dfsg-2.1build1) ... 241s Setting up python3-numpy (1:1.26.4+ds-10) ... 243s Setting up python3-slow5 (0.7.0+dfsg-2.1build1) ... 243s Setting up autopkgtest-satdep (0) ... 243s Processing triggers for man-db (2.12.1-2) ... 243s Processing triggers for libc-bin (2.39-0ubuntu9) ... 246s (Reading database ... 73705 files and directories currently installed.) 246s Removing autopkgtest-satdep (0) ... 247s autopkgtest [23:54:19]: test run-pybinding-test: [----------------------- 247s Testing with python3.12 in /tmp/autopkgtest.rFuwGA/autopkgtest_tmp: 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: examples/example.slow5, mode: r 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: b'examples/example.slow5', mode: b'r' 247s 20-Jul-24 23:54:19 - [DEBUG]: Number of read_groups: 1 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: examples/example.slow5, mode: r 247s 20-Jul-24 23:54:19 - [DEBUG]: Creating/loading index... 247s [slow5_idx_init::INFO] Index file not found. Creating an index at 'examples/example.slow5.idx'. 247s 20-Jul-24 23:54:19 - [DEBUG]: get_aux_names starting 247s 20-Jul-24 23:54:19 - [DEBUG]: get_aux_names aux_len: 0 247s 20-Jul-24 23:54:19 - [WARNING]: get_aux_names ret is NULL 247s 20-Jul-24 23:54:19 - [DEBUG]: get_aux_types starting 247s 20-Jul-24 23:54:19 - [DEBUG]: get_aux_types aux_len: 0 247s 20-Jul-24 23:54:19 - [WARNING]: get_aux_types self.s5_aux_type is NULL 247s 20-Jul-24 23:54:19 - [WARNING]: get_read unknown aux name: read_number 247s 20-Jul-24 23:54:19 - [WARNING]: get_read unknown aux name: start_mux 247s 20-Jul-24 23:54:19 - [WARNING]: get_read unknown aux name: blah 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: -1 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 247s [slow5_idx_get::ERROR] Read ID 'null_read' was not found. At src/slow5_idx.c:441 247s 20-Jul-24 23:54:19 - [DEBUG]: get_read return not 0: -7 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_hdr_keys head_len: 32 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_hdr_keys head_len: 32 247s 20-Jul-24 23:54:19 - [DEBUG]: examples/example.slow5 closed 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: examples/example2.slow5, mode: r 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 247s 20-Jul-24 23:54:19 - [DEBUG]: Number of read_groups: 4 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: examples/example2.slow5, mode: r 247s 20-Jul-24 23:54:19 - [DEBUG]: Creating/loading index... 247s [slow5_idx_init::INFO] Index file not found. Creating an index at 'examples/example2.slow5.idx'. 247s 20-Jul-24 23:54:19 - [DEBUG]: get_aux_names starting 247s 20-Jul-24 23:54:19 - [DEBUG]: get_aux_names aux_len: 5 247s 20-Jul-24 23:54:19 - [DEBUG]: get_aux_types starting 247s 20-Jul-24 23:54:19 - [DEBUG]: get_aux_types aux_len: 5 247s 20-Jul-24 23:54:19 - [WARNING]: get_read unknown aux name: blah 247s 20-Jul-24 23:54:19 - [WARNING]: get_read unknown aux name: blah 247s 20-Jul-24 23:54:19 - [DEBUG]: get_aux_names starting 247s 20-Jul-24 23:54:19 - [DEBUG]: get_aux_names aux_len: 5 247s 20-Jul-24 23:54:19 - [DEBUG]: get_aux_types starting 247s 20-Jul-24 23:54:19 - [DEBUG]: get_aux_types aux_len: 5 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: -1 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 247s 20-Jul-24 23:54:19 - [DEBUG]: examples/example2.slow5 closed 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: examples/example_write.slow5, mode: w 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: b'examples/example_write.slow5', mode: b'w' 247s 20-Jul-24 23:54:19 - [DEBUG]: Not writing blow5, skipping compression steps 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: examples/example2.slow5, mode: r 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 247s 20-Jul-24 23:54:19 - [DEBUG]: Number of read_groups: 4 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: checking header stuff... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: writting header... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: header written 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 305872 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 152707 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 305872 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 152707 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 305872 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 152707 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 305906 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 152741 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: -1 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 247s 20-Jul-24 23:54:19 - [DEBUG]: examples/example_write.slow5 closed 247s 20-Jul-24 23:54:19 - [DEBUG]: examples/example2.slow5 closed 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: examples/example_write_append.blow5, mode: w 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: b'examples/example_write_append.blow5', mode: b'w' 247s 20-Jul-24 23:54:19 - [DEBUG]: examples/example_write.slow5 already closed 247s 20-Jul-24 23:54:19 - [DEBUG]: pathname: examples/example_write.slow5 247s 20-Jul-24 23:54:19 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: total_time_yield_reads: 0.0 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: total_single_write_time: 0.03271985054016113 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: total_multi_write_time: 0.0 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: examples/example2.slow5, mode: r 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 247s 20-Jul-24 23:54:19 - [DEBUG]: Number of read_groups: 4 247s 20-Jul-24 23:54:19 - [DEBUG]: pathname: examples/example2.slow5 247s 20-Jul-24 23:54:19 - [DEBUG]: total_time_slow5_get_next: 0.03067493438720703 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: total_time_yield_reads: 0.032001495361328125 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: total_single_write_time: 0.0 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: total_multi_write_time: 0.0 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: checking header stuff... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: writting header... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: header written 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 152976 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 76384 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 152976 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 76384 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 152976 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 76384 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 153010 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 76418 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: -1 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 247s 20-Jul-24 23:54:19 - [DEBUG]: examples/example2.slow5 closed 247s 20-Jul-24 23:54:19 - [DEBUG]: examples/example_write_append.blow5 closed 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: examples/example_write_append.blow5, mode: a 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: b'examples/example_write_append.blow5', mode: b'a' 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_hdr_keys head_len: 38 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: examples/example2.slow5, mode: r 247s 20-Jul-24 23:54:19 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 247s 20-Jul-24 23:54:19 - [DEBUG]: Number of read_groups: 4 247s |==============================================| 247s | pyslow5 test launch | 247s |==============================================| 247s ['__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'] 247s slow5 file opened and object created in: 0.0004 seconds 247s ============================================== 247s get_read check, r1 247s get_read in: 0.0061 seconds 247s read_id: r1 247s read_group: 0 247s digitisation: 8192.0 247s offset: 23.0 247s range: 1467.61 247s sampling_rate: 4000.0 247s len_raw_signal: 59676 247s signal: [1039 588 588 593 586 574 570 585 588 586] 247s pylen of signal: 59676 247s AUX FIELDS: 247s read_number: None 247s start_mux: None 247s blah: None 247s ============================================== 247s get_read check, r4, converte to pA 247s get_read in: 0.0049 seconds 247s read_id: r4 247s read_group: 0 247s digitisation: 8192.0 247s offset: 23.0 247s range: 1467.61 247s sampling_rate: 4000.0 247s len_raw_signal: 59670 247s signal: [190.25902 108.92418 109.46163 109.10333 107.67012 108.38673 247s 108.745026 109.10333 111.074 108.38673 ] 247s pylen of signal: 59670 247s signal value type: 247s ============================================== 247s seq_reads check, all reads 247s seq_reads readIDs: 247s type check reads: 247s r1 247s r2 247s r3 247s r4 247s r5 247s seq_reads in: 0.0206 seconds 247s ============================================== 247s Yield check, selected reads 247s get_read_list in: 0.0 seconds 247s yielded readIDs: 247s r1 r1 247s r3 r3 247s null_read read not found, None returned 247s r5 r5 247s r2 r2 247s r1 r1 247s ============================================== 247s Get headder names 247s header names: 247s ['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'] 247s ============================================== 247s get_all_headers 247s {'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'} 247s ============================================== 247s Get headder attributes 247s flow_cell_id: FAB43577 247s exp_start_time: 1479433093 247s heatsink_temp: 33.9921875 247s asic_id: 3574887596 247s asic_id_eeprom: 0 247s asic_temp: 29.2145729 247s auto_update: 1 247s auto_update_source: https://mirror.oxfordnanoportal.com/software/MinKNOW/ 247s bream_core_version: 1.1.20.1 247s bream_is_standard: 1 247s bream_map_version: 1.1.20.1 247s bream_ont_version: 1.1.20.1 247s bream_prod_version: 1.1.20.1 247s bream_rnd_version: 0.1.1 247s device_id: MN16450 247s exp_script_name: python/recipes/nc/NC_48Hr_Sequencing_Run_FLO-MIN106_SQK-LSK108.py 247s exp_script_purpose: sequencing_run 247s exp_start_time: 1479433093 247s experiment_kit: genomic_dna 247s experiment_type: customer_qc 247s file_version: 1 247s filename: deamernanopore_20161117_fnfab43577_mn16450_sequencing_run_ma_821_r9_4_na12878_11_17_16_88738 247s flow_cell_id: FAB43577 247s heatsink_temp: 33.9921875 247s hostname: DEAMERNANOPORE 247s installation_type: map 247s local_firmware_file: 0 247s operating_system: Windows 6.2 247s protocol_run_id: a4429838-103c-497f-a824-7dffa72cfd81 247s protocols_version: 1.1.20 247s run_id: d6e473a6d513ec6bfc150c60fd4556d72f0e6d18 247s sample_frequency: 4000 247s usb_config: 1.0.11_ONT#MinION_fpga_1.0.1#ctrl#Auto 247s user_filename_input: ma_821_r9.4_na12878_11_17_16 247s version: 1.1.20 247s ============================================== 247s get_read check, 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 247s read_id: 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 247s read_group: 3 247s digitisation: 8192.0 247s offset: 6.0 247s range: 1444.86 247s sampling_rate: 4000.0 247s len_raw_signal: 38164 247s signal: [1462 1075 795 801 797 788 817 791 801 802] 247s pylen of signal: 38164 247s AUX FIELDS: 247s read_number: 2287 247s start_mux: 2 247s blah: None 247s AUX FIELDS: 247s blah: None 247s AUX FIELDS: 247s read_number: 2287 247s ============================================== 247s Get aux names 247s aux names: 247s ['channel_number', 'median_before', 'read_number', 'start_mux', 'start_time'] 247s ============================================== 247s Get aux types 247s aux types: 247s [22, 9, 2, 4, 7] 247s ============================================== 247s AUX FIELDS: 247s channel_number: 391 247s median_before: 260.557264 247s read_number: 2287 247s start_mux: 2 247s start_time: 36886851 247s ============================================== 247s seq_reads with aux: 247s type check reads: 247s r0 247s read_number 4019 247s r1 247s read_number 2287 247s r2 247s read_number 4019 247s r3 247s read_number 2287 247s r4 247s read_number 4019 247s r5 247s read_number 2287 247s 0a238451-b9ed-446d-a152-badd074006c4 247s read_number 4019 247s 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 247s read_number 2287 247s ============================================== 247s write reads no aux 247s ret: write_header(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s ============================================== 247s append reads no aux 247s ret: write_header(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s ret: write_record(): 0 247s get_all_headers 247s 20-Jul-24 23:54:19 - [DEBUG]: pathname: examples/example2.slow5 247s 20-Jul-24 23:54:19 - [DEBUG]: total_time_slow5_get_next: 0.031020402908325195 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: total_time_yield_reads: 0.03221940994262695 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: total_single_write_time: 0.0 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: total_multi_write_time: 0.0 seconds 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 152983 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 76391 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 247s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 247s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 152983 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 76391 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_write() ret: 152983 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:19 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:19 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 76391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 153017 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 76425 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: -1 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example2.slow5 closed 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example_write_append.blow5 closed 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: examples/example_write_aux.blow5, mode: w 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: b'examples/example_write_aux.blow5', mode: b'w' 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example_write_append.blow5 already closed 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example_write_append.blow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.033461570739746094 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: examples/example2.slow5, mode: r 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 248s 20-Jul-24 23:54:20 - [DEBUG]: Number of read_groups: 4 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example2.slow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.0317227840423584 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.033110618591308594 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_names starting 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_names aux_len: 5 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_types starting 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_types aux_len: 5 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checking header stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: writting header... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: header written 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 67258 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 32408 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 67258 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 32408 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 67260 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 32408 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 67298 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 32446 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: -1 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example2.slow5 closed 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example_write_aux.blow5 closed 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: examples/example_write_append_aux.blow5, mode: w 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: b'examples/example_write_append_aux.blow5', mode: b'w' 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example_write_aux.blow5 already closed 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example_write_aux.blow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.03305220603942871 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: examples/example2.slow5, mode: r 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 248s 20-Jul-24 23:54:20 - [DEBUG]: Number of read_groups: 4 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example2.slow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.031273603439331055 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.03339862823486328 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_names starting 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_names aux_len: 5 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_types starting 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_types aux_len: 5 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checking header stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: writting header... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: header written 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 153008 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 76416 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 153008 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 76416 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 153008 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 76416 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 153042 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 76450 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: -1 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example2.slow5 closed 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example_write_append_aux.blow5 closed 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: examples/example_write_append_aux.blow5, mode: a 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: b'examples/example_write_append_aux.blow5', mode: b'a' 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example_write_append.blow5 already closed 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example_write_append.blow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.03467822074890137 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: examples/example2.slow5, mode: r 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 248s 20-Jul-24 23:54:20 - [DEBUG]: Number of read_groups: 4 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example2.slow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.031156539916992188 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.033448219299316406 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_names starting 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_names aux_len: 5 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_types starting 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_types aux_len: 5 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 153015 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 76423 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 153015 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 76423 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 153015 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 76423 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 153049 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_write() ret: 76457 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: slow5_rec_free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: -1 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example2.slow5 closed 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example_write_append_aux.blow5 closed 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: examples/example2.slow5, mode: r 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 248s 20-Jul-24 23:54:20 - [DEBUG]: Number of read_groups: 4 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next_multi return: 3 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_names starting 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_names aux_len: 5 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_types starting 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_types aux_len: 5 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next_multi return: 3 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next_multi return: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next_multi has no more batches - batchsize:3 ret:2 248s 20-Jul-24 23:54:20 - [DEBUG]: seq_reads_multi timings: 248s 20-Jul-24 23:54:20 - [DEBUG]: aux_total_time: 0.00023365020751953125 248s 20-Jul-24 23:54:20 - [DEBUG]: primary_total_time: 0.00016880035400390625 248s 20-Jul-24 23:54:20 - [DEBUG]: pA_total_time: 0.0012094974517822266 248s 20-Jul-24 23:54:20 - [DEBUG]: signal_total_time: 0.00015306472778320312 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example2.slow5 closed 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: examples/example2.slow5, mode: r 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 248s 20-Jul-24 23:54:20 - [DEBUG]: Number of read_groups: 4 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example2.slow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.03193831443786621 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.0016393661499023438 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: examples/example2.slow5, mode: r 248s 20-Jul-24 23:54:20 - [DEBUG]: Creating/loading index... 248s 20-Jul-24 23:54:20 - [DEBUG]: Setting up batching... 248s 20-Jul-24 23:54:20 - [DEBUG]: read_list: ['r0', 'r1', 'r2', 'r3', 'r4', 'r5', '0a238451-b9ed-446d-a152-badd074006c4', '0d624d4b-671f-40b8-9798-84f2ccc4d7fc'] 248s 20-Jul-24 23:54:20 - [DEBUG]: batch for loop start 248s 20-Jul-24 23:54:20 - [DEBUG]: Batch: r0,r1,r2 248s 20-Jul-24 23:54:20 - [DEBUG]: Starting rid assignment 248s 20-Jul-24 23:54:20 - [DEBUG]: readID: r0, bin: b'r0' 248s 20-Jul-24 23:54:20 - [DEBUG]: readID: r1, bin: b'r1' 248s 20-Jul-24 23:54:20 - [DEBUG]: readID: r2, bin: b'r2' 248s 20-Jul-24 23:54:20 - [DEBUG]: rid assignment complete 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_batch: num_reads: 3 248s 20-Jul-24 23:54:20 - [DEBUG]: get_read_multi slow5_get_batch ret: 3 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_names starting 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_names aux_len: 5 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_types starting 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_types aux_len: 5 248s 20-Jul-24 23:54:20 - [DEBUG]: Batch: r3,r4,r5 248s 20-Jul-24 23:54:20 - [DEBUG]: Starting rid assignment 248s 20-Jul-24 23:54:20 - [DEBUG]: readID: r3, bin: b'r3' 248s 20-Jul-24 23:54:20 - [DEBUG]: readID: r4, bin: b'r4' 248s 20-Jul-24 23:54:20 - [DEBUG]: readID: r5, bin: b'r5' 248s 20-Jul-24 23:54:20 - [DEBUG]: rid assignment complete 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_batch: num_reads: 3 248s 20-Jul-24 23:54:20 - [DEBUG]: get_read_multi slow5_get_batch ret: 3 248s 20-Jul-24 23:54:20 - [DEBUG]: Batch: 0a238451-b9ed-446d-a152-badd074006c4,0d624d4b-671f-40b8-9798-84f2ccc4d7fc 248s 20-Jul-24 23:54:20 - [DEBUG]: Starting rid assignment 248s 20-Jul-24 23:54:20 - [DEBUG]: readID: 0a238451-b9ed-446d-a152-badd074006c4, bin: b'0a238451-b9ed-446d-a152-badd074006c4' 248s 20-Jul-24 23:54:20 - [DEBUG]: readID: 0d624d4b-671f-40b8-9798-84f2ccc4d7fc, bin: b'0d624d4b-671f-40b8-9798-84f2ccc4d7fc' 248s 20-Jul-24 23:54:20 - [DEBUG]: rid assignment complete 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_batch: num_reads: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: get_read_multi slow5_get_batch ret: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: seq_reads_multi timings: 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example2.slow5 closed 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: examples/example_write_aux_multi.slow5, mode: w 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: b'examples/example_write_aux_multi.slow5', mode: b'w' 248s 20-Jul-24 23:54:20 - [DEBUG]: Not writing blow5, skipping compression steps 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example_write_append_aux.blow5 already closed 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example_write_append_aux.blow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.03390216827392578 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: examples/example2.slow5, mode: r 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 248s 20-Jul-24 23:54:20 - [DEBUG]: Number of read_groups: 4 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example2.slow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.03179740905761719 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.0341191291809082 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_names starting 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_names aux_len: 5 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_types starting 248s 20-Jul-24 23:54:20 - [DEBUG]: get_aux_types aux_len: 5 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: 0 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next return: -1 248s 20-Jul-24 23:54:20 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: Setting up batching... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: batch for loop start 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checking header stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: writting header... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: header written 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_write_batch() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: free() aux 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_write_batch() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: free() aux 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: _record_type_validation running 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: doing aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux passed tests... 248s 20-Jul-24 23:54:20 - [DEBUG]: _record_type_validation: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: _record_type_validation done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_rec_init() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write assignments done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write processing raw_signal 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: self.write raw_signal done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: aux stuff done 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: slow5_write_batch() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: free() 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: free() aux 248s 20-Jul-24 23:54:20 - [DEBUG]: write_record_batch: function complete, returning 0 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example2.slow5 closed 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example_write_aux_multi.slow5 closed 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: examples/example2.slow5, mode: r 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 248s 20-Jul-24 23:54:20 - [DEBUG]: Number of read_groups: 4 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example2.slow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.030657529830932617 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.03283429145812988 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: FILE: examples/example2.slow5, mode: r 248s 20-Jul-24 23:54:20 - [DEBUG]: Creating/loading index... 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example2.slow5 closed 248s {'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'} 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ============================================== 248s write reads with aux 248s ret: write_header(): 0 248s ret: write_header(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ============================================== 248s append reads with aux 248s ret: write_header(): 0 248s ret: write_header(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ret: write_record(): 0 248s ============================================== 248s seq_reads_multi with aux: 248s type check reads: 248s r0 248s read_number 4019 248s r1 248s read_number 2287 248s r2 248s read_number 4019 248s r3 248s read_number 2287 248s r4 248s read_number 4019 248s r5 248s read_number 2287 248s 0a238451-b9ed-446d-a152-badd074006c4 248s read_number 4019 248s 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 248s read_number 2287 248s ============================================== 248s get_reads_multi with aux: 248s type check reads: 248s r0 248s read_number 4019 248s r1 248s read_number 2287 248s r2 248s read_number 4019 248s r3 248s read_number 2287 248s r4 248s read_number 4019 248s r5 248s read_number 2287 248s 0a238451-b9ed-446d-a152-badd074006c4 248s read_number 4019 248s 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 248s read_number 2287 248s ============================================== 248s write reads with aux multi 248s ret: write_header(): 0 248s ret: write_header(): 0 248s {'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)}} 248s {'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}} 248s ret: write_record(): 0 248s ============================================== 248s get all readIDs from index 248s ['r0', 'r1', 'r2', 'r3', 'r4', 'r5', '0a238451-b9ed-446d-a152-badd074006c4', '0d624d4b-671f-40b8-9798-84f2ccc4d7fc'] 248s number of reads: 8 248s ============================================== 248s done 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example.slow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.01953434944152832 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.020283222198486328 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example2.slow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.030565738677978516 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.034371376037597656 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example_write_aux_multi.slow5 already closed 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example_write_aux_multi.slow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.04118013381958008 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.10066699981689453 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example2.slow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: examples/example_write_append_aux.blow5 already closed 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example_write_append_aux.blow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.03381943702697754 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: pathname: examples/example2.slow5 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_time_yield_reads: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_single_write_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 248s 20-Jul-24 23:54:20 - [DEBUG]: total_multi_write_time: 0.0 seconds 248s autopkgtest [23:54:20]: test run-pybinding-test: -----------------------] 249s run-pybinding-test PASS 249s autopkgtest [23:54:21]: test run-pybinding-test: - - - - - - - - - - results - - - - - - - - - - 249s autopkgtest [23:54:21]: test run-pkg-test: preparing testbed 427s autopkgtest [23:57:19]: testbed dpkg architecture: ppc64el 430s autopkgtest [23:57:22]: testbed apt version: 2.9.6 430s autopkgtest [23:57:22]: @@@@@@@@@@@@@@@@@@@@ test bed setup 441s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 441s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [396 kB] 441s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [62.2 kB] 441s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 441s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4092 B] 441s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [109 kB] 441s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2116 B] 441s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 441s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 441s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [544 kB] 442s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [8952 B] 442s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1840 B] 442s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 443s Fetched 1265 kB in 1s (1426 kB/s) 443s Reading package lists... 446s Reading package lists... 446s Building dependency tree... 446s Reading state information... 447s Calculating upgrade... 447s The following packages will be upgraded: 447s libbpf1 libpython3-stdlib python3 python3-gdbm python3-minimal 447s 5 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 447s Need to get 298 kB of archives. 447s After this operation, 71.7 kB of additional disk space will be used. 447s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el python3-minimal ppc64el 3.12.4-1 [27.1 kB] 447s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el python3 ppc64el 3.12.4-1 [24.0 kB] 447s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpython3-stdlib ppc64el 3.12.4-1 [9818 B] 447s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el libbpf1 ppc64el 1:1.4.5-1 [218 kB] 447s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el python3-gdbm ppc64el 3.12.4-2 [18.9 kB] 448s Fetched 298 kB in 0s (625 kB/s) 448s (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 ... 72765 files and directories currently installed.) 448s Preparing to unpack .../python3-minimal_3.12.4-1_ppc64el.deb ... 448s Unpacking python3-minimal (3.12.4-1) over (3.12.3-0ubuntu1) ... 448s Setting up python3-minimal (3.12.4-1) ... 448s (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 ... 72765 files and directories currently installed.) 448s Preparing to unpack .../python3_3.12.4-1_ppc64el.deb ... 448s Unpacking python3 (3.12.4-1) over (3.12.3-0ubuntu1) ... 448s Preparing to unpack .../libpython3-stdlib_3.12.4-1_ppc64el.deb ... 448s Unpacking libpython3-stdlib:ppc64el (3.12.4-1) over (3.12.3-0ubuntu1) ... 448s Preparing to unpack .../libbpf1_1%3a1.4.5-1_ppc64el.deb ... 448s Unpacking libbpf1:ppc64el (1:1.4.5-1) over (1:1.4.3-1) ... 448s Preparing to unpack .../python3-gdbm_3.12.4-2_ppc64el.deb ... 448s Unpacking python3-gdbm:ppc64el (3.12.4-2) over (3.12.3-0ubuntu1) ... 448s Setting up libbpf1:ppc64el (1:1.4.5-1) ... 448s Setting up libpython3-stdlib:ppc64el (3.12.4-1) ... 448s Setting up python3 (3.12.4-1) ... 449s Setting up python3-gdbm:ppc64el (3.12.4-2) ... 449s Processing triggers for man-db (2.12.1-2) ... 449s Processing triggers for libc-bin (2.39-0ubuntu9) ... 449s Reading package lists... 449s Building dependency tree... 449s Reading state information... 450s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 450s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 450s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 450s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 450s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 452s Reading package lists... 452s Reading package lists... 452s Building dependency tree... 452s Reading state information... 452s Calculating upgrade... 452s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 452s Reading package lists... 452s Building dependency tree... 452s Reading state information... 453s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 472s Reading package lists... 473s Building dependency tree... 473s Reading state information... 473s Starting pkgProblemResolver with broken count: 0 473s Starting 2 pkgProblemResolver with broken count: 0 473s Done 473s The following additional packages will be installed: 473s build-essential cpp cpp-13 cpp-13-powerpc64le-linux-gnu 473s cpp-powerpc64le-linux-gnu g++ g++-13 g++-13-powerpc64le-linux-gnu 473s g++-powerpc64le-linux-gnu gcc gcc-13 gcc-13-base 473s gcc-13-powerpc64le-linux-gnu gcc-powerpc64le-linux-gnu libasan8 libatomic1 473s libblas3 libcc1-0 libgcc-13-dev libgfortran5 libgomp1 libisl23 libitm1 473s liblapack3 liblsan0 libmpc3 libquadmath0 libslow5-0t64 libslow5-dev 473s libstdc++-13-dev libstreamvbyte-dev libstreamvbyte0 libtsan2 libubsan1 473s python3-numpy python3-slow5 zlib1g-dev 473s Suggested packages: 473s cpp-doc gcc-13-locales cpp-13-doc gcc-13-doc gcc-multilib manpages-dev 473s autoconf automake libtool flex bison gdb gcc-doc gdb-powerpc64le-linux-gnu 473s libstdc++-13-doc gfortran python-numpy-doc python3-dev python3-pytest 473s The following NEW packages will be installed: 473s autopkgtest-satdep build-essential cpp cpp-13 cpp-13-powerpc64le-linux-gnu 473s cpp-powerpc64le-linux-gnu g++ g++-13 g++-13-powerpc64le-linux-gnu 473s g++-powerpc64le-linux-gnu gcc gcc-13 gcc-13-base 473s gcc-13-powerpc64le-linux-gnu gcc-powerpc64le-linux-gnu libasan8 libatomic1 473s libblas3 libcc1-0 libgcc-13-dev libgfortran5 libgomp1 libisl23 libitm1 473s liblapack3 liblsan0 libmpc3 libquadmath0 libslow5-0t64 libslow5-dev 473s libstdc++-13-dev libstreamvbyte-dev libstreamvbyte0 libtsan2 libubsan1 473s python3-numpy python3-slow5 zlib1g-dev 473s 0 upgraded, 38 newly installed, 0 to remove and 0 not upgraded. 473s Need to get 63.8 MB/63.8 MB of archives. 473s After this operation, 242 MB of additional disk space will be used. 473s Get:1 /tmp/autopkgtest.rFuwGA/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [764 B] 473s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el gcc-13-base ppc64el 13.3.0-3ubuntu1 [50.9 kB] 474s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisl23 ppc64el 0.26-3build1 [886 kB] 474s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el libmpc3 ppc64el 1.3.1-1build1 [62.1 kB] 474s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el cpp-13-powerpc64le-linux-gnu ppc64el 13.3.0-3ubuntu1 [9740 kB] 474s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el cpp-13 ppc64el 13.3.0-3ubuntu1 [1034 B] 474s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el cpp-powerpc64le-linux-gnu ppc64el 4:13.3.0-2ubuntu2 [5408 B] 474s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el cpp ppc64el 4:13.3.0-2ubuntu2 [22.5 kB] 474s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el libcc1-0 ppc64el 14.1.0-4ubuntu2 [48.1 kB] 474s Get:10 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgomp1 ppc64el 14.1.0-4ubuntu2 [161 kB] 474s Get:11 http://ftpmaster.internal/ubuntu oracular/main ppc64el libitm1 ppc64el 14.1.0-4ubuntu2 [31.9 kB] 474s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el libatomic1 ppc64el 14.1.0-4ubuntu2 [10.7 kB] 474s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libasan8 ppc64el 14.1.0-4ubuntu2 [2945 kB] 474s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el liblsan0 ppc64el 14.1.0-4ubuntu2 [1323 kB] 474s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libtsan2 ppc64el 14.1.0-4ubuntu2 [2694 kB] 474s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libubsan1 ppc64el 14.1.0-4ubuntu2 [1191 kB] 475s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libquadmath0 ppc64el 14.1.0-4ubuntu2 [158 kB] 475s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgcc-13-dev ppc64el 13.3.0-3ubuntu1 [1573 kB] 475s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el gcc-13-powerpc64le-linux-gnu ppc64el 13.3.0-3ubuntu1 [19.0 MB] 475s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el gcc-13 ppc64el 13.3.0-3ubuntu1 [492 kB] 475s Get:21 http://ftpmaster.internal/ubuntu oracular/main ppc64el gcc-powerpc64le-linux-gnu ppc64el 4:13.3.0-2ubuntu2 [1222 B] 475s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el gcc ppc64el 4:13.3.0-2ubuntu2 [5024 B] 475s Get:23 http://ftpmaster.internal/ubuntu oracular/main ppc64el libstdc++-13-dev ppc64el 13.3.0-3ubuntu1 [2594 kB] 475s Get:24 http://ftpmaster.internal/ubuntu oracular/main ppc64el g++-13-powerpc64le-linux-gnu ppc64el 13.3.0-3ubuntu1 [11.2 MB] 475s Get:25 http://ftpmaster.internal/ubuntu oracular/main ppc64el g++-13 ppc64el 13.3.0-3ubuntu1 [16.0 kB] 475s Get:26 http://ftpmaster.internal/ubuntu oracular/main ppc64el g++-powerpc64le-linux-gnu ppc64el 4:13.3.0-2ubuntu2 [970 B] 475s Get:27 http://ftpmaster.internal/ubuntu oracular/main ppc64el g++ ppc64el 4:13.3.0-2ubuntu2 [1090 B] 475s Get:28 http://ftpmaster.internal/ubuntu oracular/main ppc64el build-essential ppc64el 12.10ubuntu1 [4936 B] 475s Get:29 http://ftpmaster.internal/ubuntu oracular/main ppc64el libblas3 ppc64el 3.12.0-3build1 [227 kB] 475s Get:30 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgfortran5 ppc64el 14.1.0-4ubuntu2 [571 kB] 475s Get:31 http://ftpmaster.internal/ubuntu oracular/main ppc64el liblapack3 ppc64el 3.12.0-3build1 [2804 kB] 475s Get:32 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libslow5-0t64 ppc64el 0.7.0+dfsg-2.1build1 [70.7 kB] 475s Get:33 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libslow5-dev ppc64el 0.7.0+dfsg-2.1build1 [103 kB] 475s Get:34 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libstreamvbyte0 ppc64el 0.4.1-4ubuntu1 [6400 B] 475s Get:35 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libstreamvbyte-dev ppc64el 0.4.1-4ubuntu1 [6678 B] 475s Get:36 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-numpy ppc64el 1:1.26.4+ds-10 [4408 kB] 476s Get:37 http://ftpmaster.internal/ubuntu oracular/universe ppc64el python3-slow5 ppc64el 0.7.0+dfsg-2.1build1 [479 kB] 476s Get:38 http://ftpmaster.internal/ubuntu oracular/main ppc64el zlib1g-dev ppc64el 1:1.3.dfsg-3.1ubuntu2 [902 kB] 476s Fetched 63.8 MB in 2s (27.5 MB/s) 476s Selecting previously unselected package gcc-13-base:ppc64el. 476s (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 ... 72768 files and directories currently installed.) 476s Preparing to unpack .../00-gcc-13-base_13.3.0-3ubuntu1_ppc64el.deb ... 476s Unpacking gcc-13-base:ppc64el (13.3.0-3ubuntu1) ... 476s Selecting previously unselected package libisl23:ppc64el. 476s Preparing to unpack .../01-libisl23_0.26-3build1_ppc64el.deb ... 476s Unpacking libisl23:ppc64el (0.26-3build1) ... 476s Selecting previously unselected package libmpc3:ppc64el. 476s Preparing to unpack .../02-libmpc3_1.3.1-1build1_ppc64el.deb ... 476s Unpacking libmpc3:ppc64el (1.3.1-1build1) ... 476s Selecting previously unselected package cpp-13-powerpc64le-linux-gnu. 476s Preparing to unpack .../03-cpp-13-powerpc64le-linux-gnu_13.3.0-3ubuntu1_ppc64el.deb ... 476s Unpacking cpp-13-powerpc64le-linux-gnu (13.3.0-3ubuntu1) ... 476s Selecting previously unselected package cpp-13. 476s Preparing to unpack .../04-cpp-13_13.3.0-3ubuntu1_ppc64el.deb ... 476s Unpacking cpp-13 (13.3.0-3ubuntu1) ... 476s Selecting previously unselected package cpp-powerpc64le-linux-gnu. 476s Preparing to unpack .../05-cpp-powerpc64le-linux-gnu_4%3a13.3.0-2ubuntu2_ppc64el.deb ... 476s Unpacking cpp-powerpc64le-linux-gnu (4:13.3.0-2ubuntu2) ... 476s Selecting previously unselected package cpp. 476s Preparing to unpack .../06-cpp_4%3a13.3.0-2ubuntu2_ppc64el.deb ... 476s Unpacking cpp (4:13.3.0-2ubuntu2) ... 476s Selecting previously unselected package libcc1-0:ppc64el. 476s Preparing to unpack .../07-libcc1-0_14.1.0-4ubuntu2_ppc64el.deb ... 476s Unpacking libcc1-0:ppc64el (14.1.0-4ubuntu2) ... 476s Selecting previously unselected package libgomp1:ppc64el. 476s Preparing to unpack .../08-libgomp1_14.1.0-4ubuntu2_ppc64el.deb ... 476s Unpacking libgomp1:ppc64el (14.1.0-4ubuntu2) ... 476s Selecting previously unselected package libitm1:ppc64el. 476s Preparing to unpack .../09-libitm1_14.1.0-4ubuntu2_ppc64el.deb ... 476s Unpacking libitm1:ppc64el (14.1.0-4ubuntu2) ... 476s Selecting previously unselected package libatomic1:ppc64el. 476s Preparing to unpack .../10-libatomic1_14.1.0-4ubuntu2_ppc64el.deb ... 476s Unpacking libatomic1:ppc64el (14.1.0-4ubuntu2) ... 476s Selecting previously unselected package libasan8:ppc64el. 476s Preparing to unpack .../11-libasan8_14.1.0-4ubuntu2_ppc64el.deb ... 476s Unpacking libasan8:ppc64el (14.1.0-4ubuntu2) ... 477s Selecting previously unselected package liblsan0:ppc64el. 477s Preparing to unpack .../12-liblsan0_14.1.0-4ubuntu2_ppc64el.deb ... 477s Unpacking liblsan0:ppc64el (14.1.0-4ubuntu2) ... 477s Selecting previously unselected package libtsan2:ppc64el. 477s Preparing to unpack .../13-libtsan2_14.1.0-4ubuntu2_ppc64el.deb ... 477s Unpacking libtsan2:ppc64el (14.1.0-4ubuntu2) ... 477s Selecting previously unselected package libubsan1:ppc64el. 477s Preparing to unpack .../14-libubsan1_14.1.0-4ubuntu2_ppc64el.deb ... 477s Unpacking libubsan1:ppc64el (14.1.0-4ubuntu2) ... 477s Selecting previously unselected package libquadmath0:ppc64el. 477s Preparing to unpack .../15-libquadmath0_14.1.0-4ubuntu2_ppc64el.deb ... 477s Unpacking libquadmath0:ppc64el (14.1.0-4ubuntu2) ... 477s Selecting previously unselected package libgcc-13-dev:ppc64el. 477s Preparing to unpack .../16-libgcc-13-dev_13.3.0-3ubuntu1_ppc64el.deb ... 477s Unpacking libgcc-13-dev:ppc64el (13.3.0-3ubuntu1) ... 477s Selecting previously unselected package gcc-13-powerpc64le-linux-gnu. 477s Preparing to unpack .../17-gcc-13-powerpc64le-linux-gnu_13.3.0-3ubuntu1_ppc64el.deb ... 477s Unpacking gcc-13-powerpc64le-linux-gnu (13.3.0-3ubuntu1) ... 477s Selecting previously unselected package gcc-13. 477s Preparing to unpack .../18-gcc-13_13.3.0-3ubuntu1_ppc64el.deb ... 477s Unpacking gcc-13 (13.3.0-3ubuntu1) ... 477s Selecting previously unselected package gcc-powerpc64le-linux-gnu. 477s Preparing to unpack .../19-gcc-powerpc64le-linux-gnu_4%3a13.3.0-2ubuntu2_ppc64el.deb ... 477s Unpacking gcc-powerpc64le-linux-gnu (4:13.3.0-2ubuntu2) ... 477s Selecting previously unselected package gcc. 477s Preparing to unpack .../20-gcc_4%3a13.3.0-2ubuntu2_ppc64el.deb ... 477s Unpacking gcc (4:13.3.0-2ubuntu2) ... 477s Selecting previously unselected package libstdc++-13-dev:ppc64el. 477s Preparing to unpack .../21-libstdc++-13-dev_13.3.0-3ubuntu1_ppc64el.deb ... 477s Unpacking libstdc++-13-dev:ppc64el (13.3.0-3ubuntu1) ... 478s Selecting previously unselected package g++-13-powerpc64le-linux-gnu. 478s Preparing to unpack .../22-g++-13-powerpc64le-linux-gnu_13.3.0-3ubuntu1_ppc64el.deb ... 478s Unpacking g++-13-powerpc64le-linux-gnu (13.3.0-3ubuntu1) ... 478s Selecting previously unselected package g++-13. 478s Preparing to unpack .../23-g++-13_13.3.0-3ubuntu1_ppc64el.deb ... 478s Unpacking g++-13 (13.3.0-3ubuntu1) ... 478s Selecting previously unselected package g++-powerpc64le-linux-gnu. 478s Preparing to unpack .../24-g++-powerpc64le-linux-gnu_4%3a13.3.0-2ubuntu2_ppc64el.deb ... 478s Unpacking g++-powerpc64le-linux-gnu (4:13.3.0-2ubuntu2) ... 478s Selecting previously unselected package g++. 478s Preparing to unpack .../25-g++_4%3a13.3.0-2ubuntu2_ppc64el.deb ... 478s Unpacking g++ (4:13.3.0-2ubuntu2) ... 478s Selecting previously unselected package build-essential. 478s Preparing to unpack .../26-build-essential_12.10ubuntu1_ppc64el.deb ... 478s Unpacking build-essential (12.10ubuntu1) ... 478s Selecting previously unselected package libblas3:ppc64el. 478s Preparing to unpack .../27-libblas3_3.12.0-3build1_ppc64el.deb ... 478s Unpacking libblas3:ppc64el (3.12.0-3build1) ... 478s Selecting previously unselected package libgfortran5:ppc64el. 478s Preparing to unpack .../28-libgfortran5_14.1.0-4ubuntu2_ppc64el.deb ... 478s Unpacking libgfortran5:ppc64el (14.1.0-4ubuntu2) ... 478s Selecting previously unselected package liblapack3:ppc64el. 478s Preparing to unpack .../29-liblapack3_3.12.0-3build1_ppc64el.deb ... 478s Unpacking liblapack3:ppc64el (3.12.0-3build1) ... 478s Selecting previously unselected package libslow5-0t64:ppc64el. 478s Preparing to unpack .../30-libslow5-0t64_0.7.0+dfsg-2.1build1_ppc64el.deb ... 478s Unpacking libslow5-0t64:ppc64el (0.7.0+dfsg-2.1build1) ... 478s Selecting previously unselected package libslow5-dev:ppc64el. 478s Preparing to unpack .../31-libslow5-dev_0.7.0+dfsg-2.1build1_ppc64el.deb ... 478s Unpacking libslow5-dev:ppc64el (0.7.0+dfsg-2.1build1) ... 478s Selecting previously unselected package libstreamvbyte0:ppc64el. 478s Preparing to unpack .../32-libstreamvbyte0_0.4.1-4ubuntu1_ppc64el.deb ... 478s Unpacking libstreamvbyte0:ppc64el (0.4.1-4ubuntu1) ... 478s Selecting previously unselected package libstreamvbyte-dev:ppc64el. 478s Preparing to unpack .../33-libstreamvbyte-dev_0.4.1-4ubuntu1_ppc64el.deb ... 478s Unpacking libstreamvbyte-dev:ppc64el (0.4.1-4ubuntu1) ... 478s Selecting previously unselected package python3-numpy. 478s Preparing to unpack .../34-python3-numpy_1%3a1.26.4+ds-10_ppc64el.deb ... 478s Unpacking python3-numpy (1:1.26.4+ds-10) ... 479s Selecting previously unselected package python3-slow5. 479s Preparing to unpack .../35-python3-slow5_0.7.0+dfsg-2.1build1_ppc64el.deb ... 479s Unpacking python3-slow5 (0.7.0+dfsg-2.1build1) ... 479s Selecting previously unselected package zlib1g-dev:ppc64el. 479s Preparing to unpack .../36-zlib1g-dev_1%3a1.3.dfsg-3.1ubuntu2_ppc64el.deb ... 479s Unpacking zlib1g-dev:ppc64el (1:1.3.dfsg-3.1ubuntu2) ... 479s Selecting previously unselected package autopkgtest-satdep. 479s Preparing to unpack .../37-2-autopkgtest-satdep.deb ... 479s Unpacking autopkgtest-satdep (0) ... 479s Setting up libstreamvbyte0:ppc64el (0.4.1-4ubuntu1) ... 479s Setting up libgomp1:ppc64el (14.1.0-4ubuntu2) ... 479s Setting up libblas3:ppc64el (3.12.0-3build1) ... 479s update-alternatives: using /usr/lib/powerpc64le-linux-gnu/blas/libblas.so.3 to provide /usr/lib/powerpc64le-linux-gnu/libblas.so.3 (libblas.so.3-powerpc64le-linux-gnu) in auto mode 479s Setting up gcc-13-base:ppc64el (13.3.0-3ubuntu1) ... 479s Setting up libstreamvbyte-dev:ppc64el (0.4.1-4ubuntu1) ... 479s Setting up libquadmath0:ppc64el (14.1.0-4ubuntu2) ... 479s Setting up libmpc3:ppc64el (1.3.1-1build1) ... 479s Setting up libatomic1:ppc64el (14.1.0-4ubuntu2) ... 479s Setting up libslow5-0t64:ppc64el (0.7.0+dfsg-2.1build1) ... 479s Setting up libgfortran5:ppc64el (14.1.0-4ubuntu2) ... 479s Setting up libubsan1:ppc64el (14.1.0-4ubuntu2) ... 479s Setting up zlib1g-dev:ppc64el (1:1.3.dfsg-3.1ubuntu2) ... 479s Setting up libasan8:ppc64el (14.1.0-4ubuntu2) ... 479s Setting up libtsan2:ppc64el (14.1.0-4ubuntu2) ... 479s Setting up libisl23:ppc64el (0.26-3build1) ... 479s Setting up cpp-13-powerpc64le-linux-gnu (13.3.0-3ubuntu1) ... 479s Setting up libcc1-0:ppc64el (14.1.0-4ubuntu2) ... 479s Setting up liblsan0:ppc64el (14.1.0-4ubuntu2) ... 479s Setting up libitm1:ppc64el (14.1.0-4ubuntu2) ... 479s Setting up cpp-powerpc64le-linux-gnu (4:13.3.0-2ubuntu2) ... 479s Setting up liblapack3:ppc64el (3.12.0-3build1) ... 479s update-alternatives: using /usr/lib/powerpc64le-linux-gnu/lapack/liblapack.so.3 to provide /usr/lib/powerpc64le-linux-gnu/liblapack.so.3 (liblapack.so.3-powerpc64le-linux-gnu) in auto mode 479s Setting up cpp-13 (13.3.0-3ubuntu1) ... 479s Setting up libslow5-dev:ppc64el (0.7.0+dfsg-2.1build1) ... 479s Setting up python3-numpy (1:1.26.4+ds-10) ... 481s Setting up libgcc-13-dev:ppc64el (13.3.0-3ubuntu1) ... 481s Setting up cpp (4:13.3.0-2ubuntu2) ... 481s Setting up libstdc++-13-dev:ppc64el (13.3.0-3ubuntu1) ... 481s Setting up gcc-13-powerpc64le-linux-gnu (13.3.0-3ubuntu1) ... 481s Setting up gcc-13 (13.3.0-3ubuntu1) ... 481s Setting up python3-slow5 (0.7.0+dfsg-2.1build1) ... 481s Setting up g++-13-powerpc64le-linux-gnu (13.3.0-3ubuntu1) ... 481s Setting up gcc-powerpc64le-linux-gnu (4:13.3.0-2ubuntu2) ... 481s Setting up g++-powerpc64le-linux-gnu (4:13.3.0-2ubuntu2) ... 481s Setting up g++-13 (13.3.0-3ubuntu1) ... 481s Setting up gcc (4:13.3.0-2ubuntu2) ... 481s Setting up g++ (4:13.3.0-2ubuntu2) ... 481s update-alternatives: using /usr/bin/g++ to provide /usr/bin/c++ (c++) in auto mode 481s Setting up build-essential (12.10ubuntu1) ... 481s Setting up autopkgtest-satdep (0) ... 481s Processing triggers for man-db (2.12.1-2) ... 482s Processing triggers for libc-bin (2.39-0ubuntu9) ... 505s (Reading database ... 74907 files and directories currently installed.) 505s Removing autopkgtest-satdep (0) ... 535s autopkgtest [23:59:07]: test run-pkg-test: [----------------------- 535s Checking unit_test_ascii.c 536s Done! 536s Checking unit_test_binary.c 536s Done! 536s Checking unit_test_empty.c 536s Done! 536s Checking unit_test_enum.c 536s Done! 536s Checking unit_test_helpers.c 536s Done! 536s Checking unit_test_lossless.c 536s Done! 536s Checking unit_test_press.c 537s Done! 537s Checking unit_test_two_rg.c 537s Done! 537s autopkgtest [23:59:09]: test run-pkg-test: -----------------------] 559s autopkgtest [23:59:31]: test run-pkg-test: - - - - - - - - - - results - - - - - - - - - - 559s run-pkg-test PASS 559s autopkgtest [23:59:31]: @@@@@@@@@@@@@@@@@@@@ summary 559s run-pybinding-test PASS 559s run-pkg-test PASS 584s nova [W] Using flock in scalingstack-bos01-ppc64el 584s Creating nova instance adt-oracular-ppc64el-libslow5lib-20240720-235011-juju-7f2275-prod-proposed-migration-environment-3-87aca0d3-9918-412f-b1e3-501620903c01 from image adt/ubuntu-oracular-ppc64el-server-20240720.img (UUID 9e0d1223-8d9c-4f47-a977-7dfc1ecc813d)... 584s nova [W] Using flock in scalingstack-bos01-ppc64el 584s Creating nova instance adt-oracular-ppc64el-libslow5lib-20240720-235011-juju-7f2275-prod-proposed-migration-environment-3-87aca0d3-9918-412f-b1e3-501620903c01 from image adt/ubuntu-oracular-ppc64el-server-20240720.img (UUID 9e0d1223-8d9c-4f47-a977-7dfc1ecc813d)...