0s autopkgtest [21:48:59]: starting date and time: 2024-07-12 21:48:59+0000 0s autopkgtest [21:48:59]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [21:48:59]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.k84vvzhj/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:glibc --apt-upgrade libslow5lib --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=glibc/2.39-3.1ubuntu3 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos02-ppc64el-25.secgroup --name adt-oracular-ppc64el-libslow5lib-20240712-214859-juju-7f2275-prod-proposed-migration-environment-3-8003d09c-8d0c-498d-9c2d-4b5ad4f9c7f1 --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://ftpmaster.internal/ubuntu/ 187s autopkgtest [21:52:06]: testbed dpkg architecture: ppc64el 187s autopkgtest [21:52:06]: testbed apt version: 2.9.6 187s autopkgtest [21:52:06]: @@@@@@@@@@@@@@@@@@@@ test bed setup 188s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 188s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 188s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3288 B] 188s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [360 kB] 188s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [46.5 kB] 188s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [74.0 kB] 188s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2132 B] 188s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 188s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 188s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [365 kB] 189s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [9000 B] 189s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1788 B] 189s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 190s Fetched 997 kB in 1s (1169 kB/s) 191s Reading package lists... 193s Reading package lists... 193s Building dependency tree... 193s Reading state information... 193s Calculating upgrade... 193s The following packages will be upgraded: 193s libc-bin libc-dev-bin libc-devtools libc6 libc6-dev locales 194s 6 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 194s Need to get 10.1 MB of archives. 194s After this operation, 1843 kB disk space will be freed. 194s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-devtools ppc64el 2.39-3.1ubuntu3 [29.5 kB] 194s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6-dev ppc64el 2.39-3.1ubuntu3 [1982 kB] 194s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-dev-bin ppc64el 2.39-3.1ubuntu3 [21.0 kB] 194s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6 ppc64el 2.39-3.1ubuntu3 [3174 kB] 194s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-bin ppc64el 2.39-3.1ubuntu3 [720 kB] 194s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el locales all 2.39-3.1ubuntu3 [4220 kB] 195s Preconfiguring packages ... 195s Fetched 10.1 MB in 1s (10.1 MB/s) 195s (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 ... 72754 files and directories currently installed.) 195s Preparing to unpack .../libc-devtools_2.39-3.1ubuntu3_ppc64el.deb ... 195s Unpacking libc-devtools (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 195s Preparing to unpack .../libc6-dev_2.39-3.1ubuntu3_ppc64el.deb ... 195s Unpacking libc6-dev:ppc64el (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 195s Preparing to unpack .../libc-dev-bin_2.39-3.1ubuntu3_ppc64el.deb ... 195s Unpacking libc-dev-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 195s Preparing to unpack .../libc6_2.39-3.1ubuntu3_ppc64el.deb ... 195s Unpacking libc6:ppc64el (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 196s Setting up libc6:ppc64el (2.39-3.1ubuntu3) ... 196s Error: Could not restart systemd, systemd binary not working 196s (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 ... 72754 files and directories currently installed.) 196s Preparing to unpack .../libc-bin_2.39-3.1ubuntu3_ppc64el.deb ... 196s Unpacking libc-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 196s Setting up libc-bin (2.39-3.1ubuntu3) ... 196s (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 ... 72754 files and directories currently installed.) 196s Preparing to unpack .../locales_2.39-3.1ubuntu3_all.deb ... 196s Unpacking locales (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 196s Setting up locales (2.39-3.1ubuntu3) ... 197s Generating locales (this might take a while)... 198s en_US.UTF-8... done 198s Generation complete. 198s Setting up libc-dev-bin (2.39-3.1ubuntu3) ... 198s Setting up libc-devtools (2.39-3.1ubuntu3) ... 198s Setting up libc6-dev:ppc64el (2.39-3.1ubuntu3) ... 198s Processing triggers for man-db (2.12.1-2) ... 199s Processing triggers for systemd (256-1ubuntu1) ... 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. 201s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 201s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 201s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 201s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 202s Reading package lists... 202s Reading package lists... 203s Building dependency tree... 203s Reading state information... 203s Calculating upgrade... 203s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 203s Reading package lists... 203s Building dependency tree... 203s Reading state information... 203s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 206s autopkgtest [21:52:25]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 206s autopkgtest [21:52:25]: @@@@@@@@@@@@@@@@@@@@ apt-source libslow5lib 209s Get:1 http://ftpmaster.internal/ubuntu oracular/universe libslow5lib 0.7.0+dfsg-2.1build1 (dsc) [2541 B] 209s Get:2 http://ftpmaster.internal/ubuntu oracular/universe libslow5lib 0.7.0+dfsg-2.1build1 (tar) [2014 kB] 209s Get:3 http://ftpmaster.internal/ubuntu oracular/universe libslow5lib 0.7.0+dfsg-2.1build1 (diff) [8280 B] 209s gpgv: Signature made Sun Mar 31 19:37:54 2024 UTC 209s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 209s gpgv: issuer "steve.langasek@ubuntu.com" 209s gpgv: Can't check signature: No public key 209s dpkg-source: warning: cannot verify inline signature for ./libslow5lib_0.7.0+dfsg-2.1build1.dsc: no acceptable signature found 210s autopkgtest [21:52:29]: testing package libslow5lib version 0.7.0+dfsg-2.1build1 210s autopkgtest [21:52:29]: build not needed 213s autopkgtest [21:52:32]: test run-pybinding-test: preparing testbed 215s Reading package lists... 215s Building dependency tree... 215s Reading state information... 215s Starting pkgProblemResolver with broken count: 0 215s Starting 2 pkgProblemResolver with broken count: 0 215s Done 215s The following additional packages will be installed: 215s libblas3 libgfortran5 liblapack3 libslow5-0t64 libslow5-dev libstreamvbyte0 215s python3-all python3-numpy python3-slow5 215s Suggested packages: 215s gcc gfortran python-numpy-doc python3-dev python3-pytest 215s The following NEW packages will be installed: 215s autopkgtest-satdep libblas3 libgfortran5 liblapack3 libslow5-0t64 215s libslow5-dev libstreamvbyte0 python3-all python3-numpy python3-slow5 215s 0 upgraded, 10 newly installed, 0 to remove and 0 not upgraded. 215s Need to get 8672 kB/8673 kB of archives. 215s After this operation, 43.2 MB of additional disk space will be used. 215s Get:1 /tmp/autopkgtest.IPlNHv/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [728 B] 215s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libblas3 ppc64el 3.12.0-3build1 [227 kB] 216s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgfortran5 ppc64el 14.1.0-1ubuntu1 [573 kB] 216s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el liblapack3 ppc64el 3.12.0-3build1 [2804 kB] 216s Get:5 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libslow5-0t64 ppc64el 0.7.0+dfsg-2.1build1 [70.7 kB] 216s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libslow5-dev ppc64el 0.7.0+dfsg-2.1build1 [103 kB] 216s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libstreamvbyte0 ppc64el 0.4.1-4ubuntu1 [6400 B] 216s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-all ppc64el 3.12.3-0ubuntu1 [888 B] 216s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-numpy ppc64el 1:1.26.4+ds-10 [4408 kB] 216s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el python3-slow5 ppc64el 0.7.0+dfsg-2.1build1 [479 kB] 217s Fetched 8672 kB in 1s (9059 kB/s) 217s Selecting previously unselected package libblas3:ppc64el. 217s (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 ... 72754 files and directories currently installed.) 217s Preparing to unpack .../0-libblas3_3.12.0-3build1_ppc64el.deb ... 217s Unpacking libblas3:ppc64el (3.12.0-3build1) ... 217s Selecting previously unselected package libgfortran5:ppc64el. 217s Preparing to unpack .../1-libgfortran5_14.1.0-1ubuntu1_ppc64el.deb ... 217s Unpacking libgfortran5:ppc64el (14.1.0-1ubuntu1) ... 217s Selecting previously unselected package liblapack3:ppc64el. 217s Preparing to unpack .../2-liblapack3_3.12.0-3build1_ppc64el.deb ... 217s Unpacking liblapack3:ppc64el (3.12.0-3build1) ... 217s Selecting previously unselected package libslow5-0t64:ppc64el. 217s Preparing to unpack .../3-libslow5-0t64_0.7.0+dfsg-2.1build1_ppc64el.deb ... 217s Unpacking libslow5-0t64:ppc64el (0.7.0+dfsg-2.1build1) ... 217s Selecting previously unselected package libslow5-dev:ppc64el. 217s Preparing to unpack .../4-libslow5-dev_0.7.0+dfsg-2.1build1_ppc64el.deb ... 217s Unpacking libslow5-dev:ppc64el (0.7.0+dfsg-2.1build1) ... 217s Selecting previously unselected package libstreamvbyte0:ppc64el. 217s Preparing to unpack .../5-libstreamvbyte0_0.4.1-4ubuntu1_ppc64el.deb ... 217s Unpacking libstreamvbyte0:ppc64el (0.4.1-4ubuntu1) ... 217s Selecting previously unselected package python3-all. 217s Preparing to unpack .../6-python3-all_3.12.3-0ubuntu1_ppc64el.deb ... 217s Unpacking python3-all (3.12.3-0ubuntu1) ... 217s Selecting previously unselected package python3-numpy. 217s Preparing to unpack .../7-python3-numpy_1%3a1.26.4+ds-10_ppc64el.deb ... 217s Unpacking python3-numpy (1:1.26.4+ds-10) ... 217s Selecting previously unselected package python3-slow5. 217s Preparing to unpack .../8-python3-slow5_0.7.0+dfsg-2.1build1_ppc64el.deb ... 217s Unpacking python3-slow5 (0.7.0+dfsg-2.1build1) ... 217s Selecting previously unselected package autopkgtest-satdep. 217s Preparing to unpack .../9-1-autopkgtest-satdep.deb ... 217s Unpacking autopkgtest-satdep (0) ... 217s Setting up libstreamvbyte0:ppc64el (0.4.1-4ubuntu1) ... 217s Setting up python3-all (3.12.3-0ubuntu1) ... 217s Setting up libblas3:ppc64el (3.12.0-3build1) ... 217s 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 217s Setting up libslow5-0t64:ppc64el (0.7.0+dfsg-2.1build1) ... 217s Setting up libgfortran5:ppc64el (14.1.0-1ubuntu1) ... 217s Setting up liblapack3:ppc64el (3.12.0-3build1) ... 217s 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 217s Setting up libslow5-dev:ppc64el (0.7.0+dfsg-2.1build1) ... 217s Setting up python3-numpy (1:1.26.4+ds-10) ... 220s Setting up python3-slow5 (0.7.0+dfsg-2.1build1) ... 220s Setting up autopkgtest-satdep (0) ... 220s Processing triggers for man-db (2.12.1-2) ... 220s Processing triggers for libc-bin (2.39-3.1ubuntu3) ... 223s (Reading database ... 73691 files and directories currently installed.) 223s Removing autopkgtest-satdep (0) ... 223s autopkgtest [21:52:42]: test run-pybinding-test: [----------------------- 224s Testing with python3.12 in /tmp/autopkgtest.IPlNHv/autopkgtest_tmp: 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example.slow5, mode: r 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example.slow5', mode: b'r' 224s 12-Jul-24 21:52:43 - [DEBUG]: Number of read_groups: 1 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example.slow5, mode: r 224s 12-Jul-24 21:52:43 - [DEBUG]: Creating/loading index... 224s [slow5_idx_init::INFO] Index file not found. Creating an index at 'examples/example.slow5.idx'. 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_names starting 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_names aux_len: 0 224s 12-Jul-24 21:52:43 - [WARNING]: get_aux_names ret is NULL 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_types starting 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_types aux_len: 0 224s 12-Jul-24 21:52:43 - [WARNING]: get_aux_types self.s5_aux_type is NULL 224s 12-Jul-24 21:52:43 - [WARNING]: get_read unknown aux name: start_mux 224s 12-Jul-24 21:52:43 - [WARNING]: get_read unknown aux name: read_number 224s 12-Jul-24 21:52:43 - [WARNING]: get_read unknown aux name: blah 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: -1 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 224s [slow5_idx_get::ERROR] Read ID 'null_read' was not found. At src/slow5_idx.c:441 224s 12-Jul-24 21:52:43 - [DEBUG]: get_read return not 0: -7 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_hdr_keys head_len: 32 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_hdr_keys head_len: 32 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example.slow5 closed 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example2.slow5, mode: r 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 224s 12-Jul-24 21:52:43 - [DEBUG]: Number of read_groups: 4 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example2.slow5, mode: r 224s 12-Jul-24 21:52:43 - [DEBUG]: Creating/loading index... 224s [slow5_idx_init::INFO] Index file not found. Creating an index at 'examples/example2.slow5.idx'. 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_names starting 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_names aux_len: 5 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_types starting 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_types aux_len: 5 224s 12-Jul-24 21:52:43 - [WARNING]: get_read unknown aux name: blah 224s 12-Jul-24 21:52:43 - [WARNING]: get_read unknown aux name: blah 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_names starting 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_names aux_len: 5 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_types starting 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_types aux_len: 5 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: -1 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example2.slow5 closed 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example_write.slow5, mode: w 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example_write.slow5', mode: b'w' 224s 12-Jul-24 21:52:43 - [DEBUG]: Not writing blow5, skipping compression steps 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example2.slow5, mode: r 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 224s 12-Jul-24 21:52:43 - [DEBUG]: Number of read_groups: 4 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checking header stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: writting header... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: header written 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 305872 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 152707 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 305872 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 152707 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 305872 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 152707 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 305906 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 152741 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: -1 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example_write.slow5 closed 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example2.slow5 closed 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example_write_append.blow5, mode: w 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example_write_append.blow5', mode: b'w' 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example_write.slow5 already closed 224s 12-Jul-24 21:52:43 - [DEBUG]: pathname: examples/example_write.slow5 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_yield_reads: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_single_write_time: 0.03680729866027832 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example2.slow5, mode: r 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 224s 12-Jul-24 21:52:43 - [DEBUG]: Number of read_groups: 4 224s 12-Jul-24 21:52:43 - [DEBUG]: pathname: examples/example2.slow5 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_slow5_get_next: 0.03405046463012695 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_yield_reads: 0.035578250885009766 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_single_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checking header stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: writting header... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: header written 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 152976 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76384 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 152976 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76384 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 152976 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76384 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 153010 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76418 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: -1 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example2.slow5 closed 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example_write_append.blow5 closed 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example_write_append.blow5, mode: a 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example_write_append.blow5', mode: b'a' 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_hdr_keys head_len: 38 224s |==============================================| 224s | pyslow5 test launch | 224s |==============================================| 224s ['__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'] 224s slow5 file opened and object created in: 0.0008 seconds 224s ============================================== 224s get_read check, r1 224s get_read in: 0.0059 seconds 224s read_id: r1 224s read_group: 0 224s digitisation: 8192.0 224s offset: 23.0 224s range: 1467.61 224s sampling_rate: 4000.0 224s len_raw_signal: 59676 224s signal: [1039 588 588 593 586 574 570 585 588 586] 224s pylen of signal: 59676 224s AUX FIELDS: 224s read_number: None 224s start_mux: None 224s blah: None 224s ============================================== 224s get_read check, r4, converte to pA 224s get_read in: 0.0055 seconds 224s read_id: r4 224s read_group: 0 224s digitisation: 8192.0 224s offset: 23.0 224s range: 1467.61 224s sampling_rate: 4000.0 224s len_raw_signal: 59670 224s signal: [190.25902 108.92418 109.46163 109.10333 107.67012 108.38673 224s 108.745026 109.10333 111.074 108.38673 ] 224s pylen of signal: 59670 224s signal value type: 224s ============================================== 224s seq_reads check, all reads 224s seq_reads readIDs: 224s type check reads: 224s r1 224s r2 224s r3 224s r4 224s r5 224s seq_reads in: 0.0233 seconds 224s ============================================== 224s Yield check, selected reads 224s get_read_list in: 0.0 seconds 224s yielded readIDs: 224s r1 r1 224s r3 r3 224s null_read read not found, None returned 224s r5 r5 224s r2 r2 224s r1 r1 224s ============================================== 224s Get headder names 224s header names: 224s ['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'] 224s ============================================== 224s get_all_headers 224s {'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'} 224s ============================================== 224s Get headder attributes 224s flow_cell_id: FAB43577 224s exp_start_time: 1479433093 224s heatsink_temp: 33.9921875 224s asic_id: 3574887596 224s asic_id_eeprom: 0 224s asic_temp: 29.2145729 224s auto_update: 1 224s auto_update_source: https://mirror.oxfordnanoportal.com/software/MinKNOW/ 224s bream_core_version: 1.1.20.1 224s bream_is_standard: 1 224s bream_map_version: 1.1.20.1 224s bream_ont_version: 1.1.20.1 224s bream_prod_version: 1.1.20.1 224s bream_rnd_version: 0.1.1 224s device_id: MN16450 224s exp_script_name: python/recipes/nc/NC_48Hr_Sequencing_Run_FLO-MIN106_SQK-LSK108.py 224s exp_script_purpose: sequencing_run 224s exp_start_time: 1479433093 224s experiment_kit: genomic_dna 224s experiment_type: customer_qc 224s file_version: 1 224s filename: deamernanopore_20161117_fnfab43577_mn16450_sequencing_run_ma_821_r9_4_na12878_11_17_16_88738 224s flow_cell_id: FAB43577 224s heatsink_temp: 33.9921875 224s hostname: DEAMERNANOPORE 224s installation_type: map 224s local_firmware_file: 0 224s operating_system: Windows 6.2 224s protocol_run_id: a4429838-103c-497f-a824-7dffa72cfd81 224s protocols_version: 1.1.20 224s run_id: d6e473a6d513ec6bfc150c60fd4556d72f0e6d18 224s sample_frequency: 4000 224s usb_config: 1.0.11_ONT#MinION_fpga_1.0.1#ctrl#Auto 224s user_filename_input: ma_821_r9.4_na12878_11_17_16 224s version: 1.1.20 224s ============================================== 224s get_read check, 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 224s read_id: 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 224s read_group: 3 224s digitisation: 8192.0 224s offset: 6.0 224s range: 1444.86 224s sampling_rate: 4000.0 224s len_raw_signal: 38164 224s signal: [1462 1075 795 801 797 788 817 791 801 802] 224s pylen of signal: 38164 224s AUX FIELDS: 224s read_number: 2287 224s start_mux: 2 224s blah: None 224s AUX FIELDS: 224s blah: None 224s AUX FIELDS: 224s read_number: 2287 224s ============================================== 224s Get aux names 224s aux names: 224s ['channel_number', 'median_before', 'read_number', 'start_mux', 'start_time'] 224s ============================================== 224s Get aux types 224s aux types: 224s [22, 9, 2, 4, 7] 224s ============================================== 224s AUX FIELDS: 224s channel_number: 391 224s median_before: 260.557264 224s read_number: 2287 224s start_mux: 2 224s start_time: 36886851 224s ============================================== 224s seq_reads with aux: 224s type check reads: 224s r0 224s read_number 4019 224s r1 224s read_number 2287 224s r2 224s read_number 4019 224s r3 224s read_number 2287 224s r4 224s read_number 4019 224s r5 224s read_number 2287 224s 0a238451-b9ed-446d-a152-badd074006c4 224s read_number 4019 224s 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 224s read_number 2287 224s ============================================== 224s write reads no aux 224s ret: write_header(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s ============================================== 224s append reads no aux 224s ret: write_header(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s ret: write_record(): 0 224s get_all_headers 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example2.slow5, mode: r 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 224s 12-Jul-24 21:52:43 - [DEBUG]: Number of read_groups: 4 224s 12-Jul-24 21:52:43 - [DEBUG]: pathname: examples/example2.slow5 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_slow5_get_next: 0.03425264358520508 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_yield_reads: 0.035750627517700195 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_single_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 152983 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76391 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 152983 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76391 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 152983 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76391 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 153017 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76425 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: -1 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example2.slow5 closed 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example_write_append.blow5 closed 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example_write_aux.blow5, mode: w 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example_write_aux.blow5', mode: b'w' 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example_write_append.blow5 already closed 224s 12-Jul-24 21:52:43 - [DEBUG]: pathname: examples/example_write_append.blow5 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_yield_reads: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_single_write_time: 0.03728532791137695 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example2.slow5, mode: r 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 224s 12-Jul-24 21:52:43 - [DEBUG]: Number of read_groups: 4 224s 12-Jul-24 21:52:43 - [DEBUG]: pathname: examples/example2.slow5 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_slow5_get_next: 0.03405952453613281 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_yield_reads: 0.035324811935424805 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_single_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_names starting 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_names aux_len: 5 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_types starting 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_types aux_len: 5 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checking header stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: writting header... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: header written 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 281 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 4019 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 1 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 78470500 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 67258 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 391 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 2287 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 2 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 36886851 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 32408 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 281 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 4019 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 1 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 78470500 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 67258 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 391 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 2287 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 2 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 36886851 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 32408 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 281 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 4019 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 1 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 78470500 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 67260 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 391 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 2287 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 2 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 36886851 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 32408 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 281 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 4019 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 1 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 78470500 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 67298 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 391 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 2287 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 2 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 36886851 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 32446 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: -1 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example2.slow5 closed 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example_write_aux.blow5 closed 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example_write_append_aux.blow5, mode: w 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example_write_append_aux.blow5', mode: b'w' 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example_write_aux.blow5 already closed 224s 12-Jul-24 21:52:43 - [DEBUG]: pathname: examples/example_write_aux.blow5 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_yield_reads: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_single_write_time: 0.037262678146362305 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example2.slow5, mode: r 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 224s 12-Jul-24 21:52:43 - [DEBUG]: Number of read_groups: 4 224s 12-Jul-24 21:52:43 - [DEBUG]: pathname: examples/example2.slow5 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_slow5_get_next: 0.03475689888000488 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_yield_reads: 0.03704118728637695 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_single_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_names starting 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_names aux_len: 5 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_types starting 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_types aux_len: 5 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checking header stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: writting header... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: header written 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 281 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 4019 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 1 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 78470500 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 153008 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 391 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 2287 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 2 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 36886851 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76416 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 281 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 4019 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 1 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 78470500 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 153008 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 391 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 2287 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 2 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 36886851 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76416 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 281 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 4019 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 1 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 78470500 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 153008 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 391 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 2287 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 2 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 36886851 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76416 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 281 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 4019 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 1 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 78470500 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 153042 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 391 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 2287 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 2 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 36886851 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76450 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: -1 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example2.slow5 closed 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example_write_append_aux.blow5 closed 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example_write_append_aux.blow5, mode: a 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example_write_append_aux.blow5', mode: b'a' 224s 12-Jul-24 21:52:43 - [DEBUG]: examples/example_write_append.blow5 already closed 224s 12-Jul-24 21:52:43 - [DEBUG]: pathname: examples/example_write_append.blow5 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_yield_reads: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_single_write_time: 0.03699135780334473 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: examples/example2.slow5, mode: r 224s 12-Jul-24 21:52:43 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 224s 12-Jul-24 21:52:43 - [DEBUG]: Number of read_groups: 4 224s 12-Jul-24 21:52:43 - [DEBUG]: pathname: examples/example2.slow5 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_slow5_get_next: 0.034644126892089844 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_time_yield_reads: 0.036843061447143555 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_single_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: total_multi_write_time: 0.0 seconds 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_names starting 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_names aux_len: 5 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_types starting 224s 12-Jul-24 21:52:43 - [DEBUG]: get_aux_types aux_len: 5 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 281 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 4019 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 1 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 78470500 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 153015 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 391 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 2287 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 2 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 36886851 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76423 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 281 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 4019 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 1 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 78470500 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 153015 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 391 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 2287 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 2 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 36886851 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76423 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 224s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 224s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 281 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 224s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 4019 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 1 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 78470500 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 153015 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 225s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 391 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 2287 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 2 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 36886851 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 76423 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 225s 12-Jul-24 21:52:43 - [DEBUG]: slow5_get_next return: 0 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation running 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:43 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: _record_type_validation done 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_init() 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments... 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc... 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write.raw_signal malloc done 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write assignments done 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write processing raw_signal 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: self.write raw_signal done 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff... 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: channel_number: 281 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running... 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string type: 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: median_before: 231.363533 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: read_number: 4019 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_mux: 1 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: checked_aux: start_time: 78470500 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: aux stuff done 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_write() ret: 153049 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: slow5_rec_free() 225s 12-Jul-24 21:52:43 - [DEBUG]: write_record: function complete, returning 0 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next return: 0 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: _record_type_validation running 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: _record_type_validation done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: slow5_rec_init() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: self.write assignments... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: self.write.raw_signal malloc... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: self.write.raw_signal malloc done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: self.write assignments done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: self.write processing raw_signal 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: self.write raw_signal done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: checked_aux: channel_number: 391 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: slow5_aux_set_string running... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: slow5_aux_set_string type: 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: slow5_aux_set_string running done: ret = 0 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: checked_aux: median_before: 260.557264 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: checked_aux: read_number: 2287 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: checked_aux: start_mux: 2 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: checked_aux: start_time: 36886851 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: slow5_write() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: slow5_write() ret: 76457 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: slow5_rec_free() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record: function complete, returning 0 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next return: -1 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 225s 12-Jul-24 21:52:44 - [DEBUG]: examples/example2.slow5 closed 225s 12-Jul-24 21:52:44 - [DEBUG]: examples/example_write_append_aux.blow5 closed 225s 12-Jul-24 21:52:44 - [DEBUG]: FILE: examples/example2.slow5, mode: r 225s 12-Jul-24 21:52:44 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 225s 12-Jul-24 21:52:44 - [DEBUG]: Number of read_groups: 4 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next_multi return: 3 225s 12-Jul-24 21:52:44 - [DEBUG]: get_aux_names starting 225s 12-Jul-24 21:52:44 - [DEBUG]: get_aux_names aux_len: 5 225s 12-Jul-24 21:52:44 - [DEBUG]: get_aux_types starting 225s 12-Jul-24 21:52:44 - [DEBUG]: get_aux_types aux_len: 5 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next_multi return: 3 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next_multi return: 2 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next_multi has no more batches - batchsize:3 ret:2 225s 12-Jul-24 21:52:44 - [DEBUG]: seq_reads_multi timings: 225s 12-Jul-24 21:52:44 - [DEBUG]: aux_total_time: 0.0002913475036621094 225s 12-Jul-24 21:52:44 - [DEBUG]: primary_total_time: 0.0002162456512451172 225s 12-Jul-24 21:52:44 - [DEBUG]: pA_total_time: 0.0016894340515136719 225s 12-Jul-24 21:52:44 - [DEBUG]: signal_total_time: 0.00019884109497070312 225s 12-Jul-24 21:52:44 - [DEBUG]: examples/example2.slow5 closed 225s 12-Jul-24 21:52:44 - [DEBUG]: FILE: examples/example2.slow5, mode: r 225s 12-Jul-24 21:52:44 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 225s 12-Jul-24 21:52:44 - [DEBUG]: Number of read_groups: 4 225s 12-Jul-24 21:52:44 - [DEBUG]: pathname: examples/example2.slow5 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_slow5_get_next: 0.03455972671508789 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_yield_reads: 0.0022230148315429688 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_single_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: FILE: examples/example2.slow5, mode: r 225s 12-Jul-24 21:52:44 - [DEBUG]: Creating/loading index... 225s 12-Jul-24 21:52:44 - [DEBUG]: Setting up batching... 225s 12-Jul-24 21:52:44 - [DEBUG]: read_list: ['r0', 'r1', 'r2', 'r3', 'r4', 'r5', '0a238451-b9ed-446d-a152-badd074006c4', '0d624d4b-671f-40b8-9798-84f2ccc4d7fc'] 225s 12-Jul-24 21:52:44 - [DEBUG]: batch for loop start 225s 12-Jul-24 21:52:44 - [DEBUG]: Batch: r0,r1,r2 225s 12-Jul-24 21:52:44 - [DEBUG]: Starting rid assignment 225s 12-Jul-24 21:52:44 - [DEBUG]: readID: r0, bin: b'r0' 225s 12-Jul-24 21:52:44 - [DEBUG]: readID: r1, bin: b'r1' 225s 12-Jul-24 21:52:44 - [DEBUG]: readID: r2, bin: b'r2' 225s 12-Jul-24 21:52:44 - [DEBUG]: rid assignment complete 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_batch: num_reads: 3 225s 12-Jul-24 21:52:44 - [DEBUG]: get_read_multi slow5_get_batch ret: 3 225s 12-Jul-24 21:52:44 - [DEBUG]: get_aux_names starting 225s 12-Jul-24 21:52:44 - [DEBUG]: get_aux_names aux_len: 5 225s 12-Jul-24 21:52:44 - [DEBUG]: get_aux_types starting 225s 12-Jul-24 21:52:44 - [DEBUG]: get_aux_types aux_len: 5 225s 12-Jul-24 21:52:44 - [DEBUG]: Batch: r3,r4,r5 225s 12-Jul-24 21:52:44 - [DEBUG]: Starting rid assignment 225s 12-Jul-24 21:52:44 - [DEBUG]: readID: r3, bin: b'r3' 225s 12-Jul-24 21:52:44 - [DEBUG]: readID: r4, bin: b'r4' 225s 12-Jul-24 21:52:44 - [DEBUG]: readID: r5, bin: b'r5' 225s 12-Jul-24 21:52:44 - [DEBUG]: rid assignment complete 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_batch: num_reads: 3 225s 12-Jul-24 21:52:44 - [DEBUG]: get_read_multi slow5_get_batch ret: 3 225s 12-Jul-24 21:52:44 - [DEBUG]: Batch: 0a238451-b9ed-446d-a152-badd074006c4,0d624d4b-671f-40b8-9798-84f2ccc4d7fc 225s 12-Jul-24 21:52:44 - [DEBUG]: Starting rid assignment 225s 12-Jul-24 21:52:44 - [DEBUG]: readID: 0a238451-b9ed-446d-a152-badd074006c4, bin: b'0a238451-b9ed-446d-a152-badd074006c4' 225s 12-Jul-24 21:52:44 - [DEBUG]: readID: 0d624d4b-671f-40b8-9798-84f2ccc4d7fc, bin: b'0d624d4b-671f-40b8-9798-84f2ccc4d7fc' 225s 12-Jul-24 21:52:44 - [DEBUG]: rid assignment complete 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_batch: num_reads: 2 225s 12-Jul-24 21:52:44 - [DEBUG]: get_read_multi slow5_get_batch ret: 2 225s 12-Jul-24 21:52:44 - [DEBUG]: seq_reads_multi timings: 225s 12-Jul-24 21:52:44 - [DEBUG]: examples/example2.slow5 closed 225s 12-Jul-24 21:52:44 - [DEBUG]: FILE: examples/example_write_aux_multi.slow5, mode: w 225s 12-Jul-24 21:52:44 - [DEBUG]: FILE: b'examples/example_write_aux_multi.slow5', mode: b'w' 225s 12-Jul-24 21:52:44 - [DEBUG]: Not writing blow5, skipping compression steps 225s 12-Jul-24 21:52:44 - [DEBUG]: examples/example_write_append_aux.blow5 already closed 225s 12-Jul-24 21:52:44 - [DEBUG]: pathname: examples/example_write_append_aux.blow5 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_yield_reads: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_single_write_time: 0.03783583641052246 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: FILE: examples/example2.slow5, mode: r 225s 12-Jul-24 21:52:44 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 225s 12-Jul-24 21:52:44 - [DEBUG]: Number of read_groups: 4 225s 12-Jul-24 21:52:44 - [DEBUG]: pathname: examples/example2.slow5 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_slow5_get_next: 0.03440284729003906 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_yield_reads: 0.036258697509765625 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_single_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next return: 0 225s 12-Jul-24 21:52:44 - [DEBUG]: get_aux_names starting 225s 12-Jul-24 21:52:44 - [DEBUG]: get_aux_names aux_len: 5 225s 12-Jul-24 21:52:44 - [DEBUG]: get_aux_types starting 225s 12-Jul-24 21:52:44 - [DEBUG]: get_aux_types aux_len: 5 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next return: 0 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next return: 0 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next return: 0 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next return: 0 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next return: 0 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next return: 0 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next return: 0 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next return: -1 225s 12-Jul-24 21:52:44 - [DEBUG]: slow5_get_next reached end of file (EOF)(-1): -1: ['SLOW5_ERR_EOF', 'End Of File reached'] 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: Setting up batching... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: batch for loop start 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: _record_type_validation running 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: _record_type_validation done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checking header stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: writting header... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: header written 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_rec_init() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write processing raw_signal 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write raw_signal done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_rec_init() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write processing raw_signal 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write raw_signal done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_rec_init() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write processing raw_signal 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write raw_signal done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_write_batch() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: free() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: free() aux 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: _record_type_validation running 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: _record_type_validation done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_rec_init() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write processing raw_signal 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write raw_signal done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_rec_init() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write processing raw_signal 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write raw_signal done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_rec_init() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write processing raw_signal 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write raw_signal done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_write_batch() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: free() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: free() aux 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: _record_type_validation running 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: doing aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux passed tests... 225s 12-Jul-24 21:52:44 - [DEBUG]: _record_type_validation: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: _record_type_validation done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_rec_init() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write processing raw_signal 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write raw_signal done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: channel_number: 281 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: median_before: 231.363533 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: read_number: 4019 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_mux: 1 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_time: 78470500 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_rec_init() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write.raw_signal malloc done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write assignments done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write processing raw_signal 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: self.write raw_signal done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: channel_number: 391 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running... 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string type: 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_aux_set_string running done: ret = 0 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: median_before: 260.557264 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: read_number: 2287 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_mux: 2 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: checked_aux: start_time: 36886851 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: aux stuff done 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: slow5_write_batch() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: free() 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: free() aux 225s 12-Jul-24 21:52:44 - [DEBUG]: write_record_batch: function complete, returning 0 225s 12-Jul-24 21:52:44 - [DEBUG]: examples/example2.slow5 closed 225s 12-Jul-24 21:52:44 - [DEBUG]: examples/example_write_aux_multi.slow5 closed 225s 12-Jul-24 21:52:44 - [DEBUG]: FILE: examples/example2.slow5, mode: r 225s 12-Jul-24 21:52:44 - [DEBUG]: FILE: b'examples/example2.slow5', mode: b'r' 225s 12-Jul-24 21:52:44 - [DEBUG]: Number of read_groups: 4 225s 12-Jul-24 21:52:44 - [DEBUG]: pathname: examples/example2.slow5 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_slow5_get_next: 0.03325319290161133 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_yield_reads: 0.034746408462524414 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_single_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: FILE: examples/example2.slow5, mode: r 225s 12-Jul-24 21:52:44 - [DEBUG]: Creating/loading index... 225s 12-Jul-24 21:52:44 - [DEBUG]: examples/example2.slow5 closed 225s {'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'} 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ============================================== 225s write reads with aux 225s ret: write_header(): 0 225s ret: write_header(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ============================================== 225s append reads with aux 225s ret: write_header(): 0 225s ret: write_header(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ret: write_record(): 0 225s ============================================== 225s seq_reads_multi with aux: 225s type check reads: 225s r0 225s read_number 4019 225s r1 225s read_number 2287 225s r2 225s read_number 4019 225s r3 225s read_number 2287 225s r4 225s read_number 4019 225s r5 225s read_number 2287 225s 0a238451-b9ed-446d-a152-badd074006c4 225s read_number 4019 225s 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 225s read_number 2287 225s ============================================== 225s get_reads_multi with aux: 225s type check reads: 225s r0 225s read_number 4019 225s r1 225s read_number 2287 225s r2 225s read_number 4019 225s r3 225s read_number 2287 225s r4 225s read_number 4019 225s r5 225s read_number 2287 225s 0a238451-b9ed-446d-a152-badd074006c4 225s read_number 4019 225s 0d624d4b-671f-40b8-9798-84f2ccc4d7fc 225s read_number 2287 225s ============================================== 225s write reads with aux multi 225s ret: write_header(): 0 225s ret: write_header(): 0 225s {'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)}} 225s {'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}} 225s ret: write_record(): 0 225s ============================================== 225s get all readIDs from index 225s ['r0', 'r1', 'r2', 'r3', 'r4', 'r5', '0a238451-b9ed-446d-a152-badd074006c4', '0d624d4b-671f-40b8-9798-84f2ccc4d7fc'] 225s number of reads: 8 225s ============================================== 225s done 225s 12-Jul-24 21:52:44 - [DEBUG]: pathname: examples/example.slow5 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_slow5_get_next: 0.021808862686157227 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_yield_reads: 0.02293539047241211 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_single_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: pathname: examples/example2.slow5 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_slow5_get_next: 0.03334856033325195 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_yield_reads: 0.03688240051269531 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_single_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: examples/example_write_aux_multi.slow5 already closed 225s 12-Jul-24 21:52:44 - [DEBUG]: pathname: examples/example_write_aux_multi.slow5 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_yield_reads: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_single_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_signal_time: 0.04596281051635742 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_time: 0.10662961006164551 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: pathname: examples/example2.slow5 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_yield_reads: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_single_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: examples/example_write_append_aux.blow5 already closed 225s 12-Jul-24 21:52:44 - [DEBUG]: pathname: examples/example_write_append_aux.blow5 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_yield_reads: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_single_write_time: 0.03830742835998535 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: pathname: examples/example2.slow5 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_slow5_get_next: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_time_yield_reads: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_single_write_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_signal_time: 0.0 seconds 225s 12-Jul-24 21:52:44 - [DEBUG]: total_multi_write_time: 0.0 seconds 225s autopkgtest [21:52:44]: test run-pybinding-test: -----------------------] 226s autopkgtest [21:52:45]: test run-pybinding-test: - - - - - - - - - - results - - - - - - - - - - 226s run-pybinding-test PASS 226s autopkgtest [21:52:45]: test run-pkg-test: preparing testbed 415s autopkgtest [21:55:54]: testbed dpkg architecture: ppc64el 415s autopkgtest [21:55:54]: testbed apt version: 2.9.6 415s autopkgtest [21:55:54]: @@@@@@@@@@@@@@@@@@@@ test bed setup 416s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 417s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [360 kB] 417s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [46.5 kB] 417s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3288 B] 417s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 417s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [74.0 kB] 417s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2132 B] 417s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 417s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 417s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [365 kB] 417s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [9000 B] 417s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1788 B] 417s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 419s Fetched 997 kB in 1s (1299 kB/s) 419s Reading package lists... 421s Reading package lists... 421s Building dependency tree... 421s Reading state information... 421s Calculating upgrade... 422s The following packages will be upgraded: 422s libc-bin libc-dev-bin libc-devtools libc6 libc6-dev locales 422s 6 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 422s Need to get 10.1 MB of archives. 422s After this operation, 1843 kB disk space will be freed. 422s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-devtools ppc64el 2.39-3.1ubuntu3 [29.5 kB] 422s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6-dev ppc64el 2.39-3.1ubuntu3 [1982 kB] 422s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-dev-bin ppc64el 2.39-3.1ubuntu3 [21.0 kB] 422s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6 ppc64el 2.39-3.1ubuntu3 [3174 kB] 422s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-bin ppc64el 2.39-3.1ubuntu3 [720 kB] 422s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el locales all 2.39-3.1ubuntu3 [4220 kB] 423s Preconfiguring packages ... 423s Fetched 10.1 MB in 1s (10.4 MB/s) 423s (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 ... 72754 files and directories currently installed.) 423s Preparing to unpack .../libc-devtools_2.39-3.1ubuntu3_ppc64el.deb ... 423s Unpacking libc-devtools (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 423s Preparing to unpack .../libc6-dev_2.39-3.1ubuntu3_ppc64el.deb ... 423s Unpacking libc6-dev:ppc64el (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 423s Preparing to unpack .../libc-dev-bin_2.39-3.1ubuntu3_ppc64el.deb ... 423s Unpacking libc-dev-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 423s Preparing to unpack .../libc6_2.39-3.1ubuntu3_ppc64el.deb ... 423s Unpacking libc6:ppc64el (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 424s Setting up libc6:ppc64el (2.39-3.1ubuntu3) ... 424s Error: Could not restart systemd, systemd binary not working 424s (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 ... 72754 files and directories currently installed.) 424s Preparing to unpack .../libc-bin_2.39-3.1ubuntu3_ppc64el.deb ... 424s Unpacking libc-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 424s Setting up libc-bin (2.39-3.1ubuntu3) ... 424s (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 ... 72754 files and directories currently installed.) 424s Preparing to unpack .../locales_2.39-3.1ubuntu3_all.deb ... 424s Unpacking locales (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 424s Setting up locales (2.39-3.1ubuntu3) ... 425s Generating locales (this might take a while)... 426s en_US.UTF-8... done 426s Generation complete. 426s Setting up libc-dev-bin (2.39-3.1ubuntu3) ... 426s Setting up libc-devtools (2.39-3.1ubuntu3) ... 426s Setting up libc6-dev:ppc64el (2.39-3.1ubuntu3) ... 426s Processing triggers for man-db (2.12.1-2) ... 427s Processing triggers for systemd (256-1ubuntu1) ... 428s Reading package lists... 429s Building dependency tree... 429s Reading state information... 429s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 429s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 429s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 429s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 430s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 431s Reading package lists... 431s Reading package lists... 431s Building dependency tree... 431s Reading state information... 431s Calculating upgrade... 431s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 431s Reading package lists... 431s Building dependency tree... 431s Reading state information... 432s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 436s Reading package lists... 436s Building dependency tree... 436s Reading state information... 436s Starting pkgProblemResolver with broken count: 0 436s Starting 2 pkgProblemResolver with broken count: 0 436s Done 437s The following additional packages will be installed: 437s build-essential cpp cpp-13 cpp-13-powerpc64le-linux-gnu 437s cpp-powerpc64le-linux-gnu g++ g++-13 g++-13-powerpc64le-linux-gnu 437s g++-powerpc64le-linux-gnu gcc gcc-13 gcc-13-base 437s gcc-13-powerpc64le-linux-gnu gcc-powerpc64le-linux-gnu libasan8 libatomic1 437s libblas3 libcc1-0 libgcc-13-dev libgfortran5 libgomp1 libisl23 libitm1 437s liblapack3 liblsan0 libmpc3 libquadmath0 libslow5-0t64 libslow5-dev 437s libstdc++-13-dev libstreamvbyte-dev libstreamvbyte0 libtsan2 libubsan1 437s python3-numpy python3-slow5 zlib1g-dev 437s Suggested packages: 437s cpp-doc gcc-13-locales cpp-13-doc gcc-13-doc gcc-multilib manpages-dev 437s autoconf automake libtool flex bison gdb gcc-doc gdb-powerpc64le-linux-gnu 437s libstdc++-13-doc gfortran python-numpy-doc python3-dev python3-pytest 437s The following NEW packages will be installed: 437s autopkgtest-satdep build-essential cpp cpp-13 cpp-13-powerpc64le-linux-gnu 437s cpp-powerpc64le-linux-gnu g++ g++-13 g++-13-powerpc64le-linux-gnu 437s g++-powerpc64le-linux-gnu gcc gcc-13 gcc-13-base 437s gcc-13-powerpc64le-linux-gnu gcc-powerpc64le-linux-gnu libasan8 libatomic1 437s libblas3 libcc1-0 libgcc-13-dev libgfortran5 libgomp1 libisl23 libitm1 437s liblapack3 liblsan0 libmpc3 libquadmath0 libslow5-0t64 libslow5-dev 437s libstdc++-13-dev libstreamvbyte-dev libstreamvbyte0 libtsan2 libubsan1 437s python3-numpy python3-slow5 zlib1g-dev 437s 0 upgraded, 38 newly installed, 0 to remove and 0 not upgraded. 437s Need to get 67.3 MB/67.3 MB of archives. 437s After this operation, 262 MB of additional disk space will be used. 437s Get:1 /tmp/autopkgtest.IPlNHv/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [764 B] 437s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el gcc-13-base ppc64el 13.2.0-23ubuntu4 [49.0 kB] 437s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisl23 ppc64el 0.26-3build1 [886 kB] 437s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el libmpc3 ppc64el 1.3.1-1build1 [62.1 kB] 437s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el cpp-13-powerpc64le-linux-gnu ppc64el 13.2.0-23ubuntu4 [10.7 MB] 438s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el cpp-13 ppc64el 13.2.0-23ubuntu4 [1038 B] 438s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el cpp-powerpc64le-linux-gnu ppc64el 4:13.2.0-7ubuntu1 [5330 B] 438s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el cpp ppc64el 4:13.2.0-7ubuntu1 [22.5 kB] 438s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el libcc1-0 ppc64el 14.1.0-1ubuntu1 [48.1 kB] 438s Get:10 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgomp1 ppc64el 14.1.0-1ubuntu1 [161 kB] 438s Get:11 http://ftpmaster.internal/ubuntu oracular/main ppc64el libitm1 ppc64el 14.1.0-1ubuntu1 [32.4 kB] 438s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el libatomic1 ppc64el 14.1.0-1ubuntu1 [10.7 kB] 438s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libasan8 ppc64el 14.1.0-1ubuntu1 [2971 kB] 438s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el liblsan0 ppc64el 14.1.0-1ubuntu1 [1328 kB] 438s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libtsan2 ppc64el 14.1.0-1ubuntu1 [2708 kB] 438s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libubsan1 ppc64el 14.1.0-1ubuntu1 [1196 kB] 438s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libquadmath0 ppc64el 14.1.0-1ubuntu1 [158 kB] 438s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgcc-13-dev ppc64el 13.2.0-23ubuntu4 [1580 kB] 439s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el gcc-13-powerpc64le-linux-gnu ppc64el 13.2.0-23ubuntu4 [20.6 MB] 440s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el gcc-13 ppc64el 13.2.0-23ubuntu4 [482 kB] 440s Get:21 http://ftpmaster.internal/ubuntu oracular/main ppc64el gcc-powerpc64le-linux-gnu ppc64el 4:13.2.0-7ubuntu1 [1224 B] 440s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el gcc ppc64el 4:13.2.0-7ubuntu1 [5022 B] 440s Get:23 http://ftpmaster.internal/ubuntu oracular/main ppc64el libstdc++-13-dev ppc64el 13.2.0-23ubuntu4 [2512 kB] 440s Get:24 http://ftpmaster.internal/ubuntu oracular/main ppc64el g++-13-powerpc64le-linux-gnu ppc64el 13.2.0-23ubuntu4 [12.2 MB] 441s Get:25 http://ftpmaster.internal/ubuntu oracular/main ppc64el g++-13 ppc64el 13.2.0-23ubuntu4 [14.5 kB] 441s Get:26 http://ftpmaster.internal/ubuntu oracular/main ppc64el g++-powerpc64le-linux-gnu ppc64el 4:13.2.0-7ubuntu1 [968 B] 441s Get:27 http://ftpmaster.internal/ubuntu oracular/main ppc64el g++ ppc64el 4:13.2.0-7ubuntu1 [1086 B] 441s Get:28 http://ftpmaster.internal/ubuntu oracular/main ppc64el build-essential ppc64el 12.10ubuntu1 [4936 B] 441s Get:29 http://ftpmaster.internal/ubuntu oracular/main ppc64el libblas3 ppc64el 3.12.0-3build1 [227 kB] 441s Get:30 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgfortran5 ppc64el 14.1.0-1ubuntu1 [573 kB] 442s Get:31 http://ftpmaster.internal/ubuntu oracular/main ppc64el liblapack3 ppc64el 3.12.0-3build1 [2804 kB] 442s Get:32 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libslow5-0t64 ppc64el 0.7.0+dfsg-2.1build1 [70.7 kB] 442s Get:33 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libslow5-dev ppc64el 0.7.0+dfsg-2.1build1 [103 kB] 442s Get:34 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libstreamvbyte0 ppc64el 0.4.1-4ubuntu1 [6400 B] 442s Get:35 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libstreamvbyte-dev ppc64el 0.4.1-4ubuntu1 [6678 B] 442s Get:36 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-numpy ppc64el 1:1.26.4+ds-10 [4408 kB] 442s Get:37 http://ftpmaster.internal/ubuntu oracular/universe ppc64el python3-slow5 ppc64el 0.7.0+dfsg-2.1build1 [479 kB] 442s Get:38 http://ftpmaster.internal/ubuntu oracular/main ppc64el zlib1g-dev ppc64el 1:1.3.dfsg-3.1ubuntu2 [902 kB] 443s Fetched 67.3 MB in 6s (11.5 MB/s) 443s Selecting previously unselected package gcc-13-base:ppc64el. 443s (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 ... 72754 files and directories currently installed.) 443s Preparing to unpack .../00-gcc-13-base_13.2.0-23ubuntu4_ppc64el.deb ... 443s Unpacking gcc-13-base:ppc64el (13.2.0-23ubuntu4) ... 443s Selecting previously unselected package libisl23:ppc64el. 443s Preparing to unpack .../01-libisl23_0.26-3build1_ppc64el.deb ... 443s Unpacking libisl23:ppc64el (0.26-3build1) ... 443s Selecting previously unselected package libmpc3:ppc64el. 443s Preparing to unpack .../02-libmpc3_1.3.1-1build1_ppc64el.deb ... 443s Unpacking libmpc3:ppc64el (1.3.1-1build1) ... 443s Selecting previously unselected package cpp-13-powerpc64le-linux-gnu. 443s Preparing to unpack .../03-cpp-13-powerpc64le-linux-gnu_13.2.0-23ubuntu4_ppc64el.deb ... 443s Unpacking cpp-13-powerpc64le-linux-gnu (13.2.0-23ubuntu4) ... 443s Selecting previously unselected package cpp-13. 443s Preparing to unpack .../04-cpp-13_13.2.0-23ubuntu4_ppc64el.deb ... 443s Unpacking cpp-13 (13.2.0-23ubuntu4) ... 443s Selecting previously unselected package cpp-powerpc64le-linux-gnu. 443s Preparing to unpack .../05-cpp-powerpc64le-linux-gnu_4%3a13.2.0-7ubuntu1_ppc64el.deb ... 443s Unpacking cpp-powerpc64le-linux-gnu (4:13.2.0-7ubuntu1) ... 443s Selecting previously unselected package cpp. 443s Preparing to unpack .../06-cpp_4%3a13.2.0-7ubuntu1_ppc64el.deb ... 443s Unpacking cpp (4:13.2.0-7ubuntu1) ... 443s Selecting previously unselected package libcc1-0:ppc64el. 443s Preparing to unpack .../07-libcc1-0_14.1.0-1ubuntu1_ppc64el.deb ... 443s Unpacking libcc1-0:ppc64el (14.1.0-1ubuntu1) ... 443s Selecting previously unselected package libgomp1:ppc64el. 443s Preparing to unpack .../08-libgomp1_14.1.0-1ubuntu1_ppc64el.deb ... 443s Unpacking libgomp1:ppc64el (14.1.0-1ubuntu1) ... 443s Selecting previously unselected package libitm1:ppc64el. 443s Preparing to unpack .../09-libitm1_14.1.0-1ubuntu1_ppc64el.deb ... 443s Unpacking libitm1:ppc64el (14.1.0-1ubuntu1) ... 443s Selecting previously unselected package libatomic1:ppc64el. 443s Preparing to unpack .../10-libatomic1_14.1.0-1ubuntu1_ppc64el.deb ... 443s Unpacking libatomic1:ppc64el (14.1.0-1ubuntu1) ... 443s Selecting previously unselected package libasan8:ppc64el. 443s Preparing to unpack .../11-libasan8_14.1.0-1ubuntu1_ppc64el.deb ... 443s Unpacking libasan8:ppc64el (14.1.0-1ubuntu1) ... 443s Selecting previously unselected package liblsan0:ppc64el. 443s Preparing to unpack .../12-liblsan0_14.1.0-1ubuntu1_ppc64el.deb ... 443s Unpacking liblsan0:ppc64el (14.1.0-1ubuntu1) ... 443s Selecting previously unselected package libtsan2:ppc64el. 443s Preparing to unpack .../13-libtsan2_14.1.0-1ubuntu1_ppc64el.deb ... 443s Unpacking libtsan2:ppc64el (14.1.0-1ubuntu1) ... 443s Selecting previously unselected package libubsan1:ppc64el. 443s Preparing to unpack .../14-libubsan1_14.1.0-1ubuntu1_ppc64el.deb ... 443s Unpacking libubsan1:ppc64el (14.1.0-1ubuntu1) ... 444s Selecting previously unselected package libquadmath0:ppc64el. 444s Preparing to unpack .../15-libquadmath0_14.1.0-1ubuntu1_ppc64el.deb ... 444s Unpacking libquadmath0:ppc64el (14.1.0-1ubuntu1) ... 444s Selecting previously unselected package libgcc-13-dev:ppc64el. 444s Preparing to unpack .../16-libgcc-13-dev_13.2.0-23ubuntu4_ppc64el.deb ... 444s Unpacking libgcc-13-dev:ppc64el (13.2.0-23ubuntu4) ... 444s Selecting previously unselected package gcc-13-powerpc64le-linux-gnu. 444s Preparing to unpack .../17-gcc-13-powerpc64le-linux-gnu_13.2.0-23ubuntu4_ppc64el.deb ... 444s Unpacking gcc-13-powerpc64le-linux-gnu (13.2.0-23ubuntu4) ... 444s Selecting previously unselected package gcc-13. 444s Preparing to unpack .../18-gcc-13_13.2.0-23ubuntu4_ppc64el.deb ... 444s Unpacking gcc-13 (13.2.0-23ubuntu4) ... 444s Selecting previously unselected package gcc-powerpc64le-linux-gnu. 444s Preparing to unpack .../19-gcc-powerpc64le-linux-gnu_4%3a13.2.0-7ubuntu1_ppc64el.deb ... 444s Unpacking gcc-powerpc64le-linux-gnu (4:13.2.0-7ubuntu1) ... 444s Selecting previously unselected package gcc. 444s Preparing to unpack .../20-gcc_4%3a13.2.0-7ubuntu1_ppc64el.deb ... 444s Unpacking gcc (4:13.2.0-7ubuntu1) ... 444s Selecting previously unselected package libstdc++-13-dev:ppc64el. 444s Preparing to unpack .../21-libstdc++-13-dev_13.2.0-23ubuntu4_ppc64el.deb ... 444s Unpacking libstdc++-13-dev:ppc64el (13.2.0-23ubuntu4) ... 445s Selecting previously unselected package g++-13-powerpc64le-linux-gnu. 445s Preparing to unpack .../22-g++-13-powerpc64le-linux-gnu_13.2.0-23ubuntu4_ppc64el.deb ... 445s Unpacking g++-13-powerpc64le-linux-gnu (13.2.0-23ubuntu4) ... 445s Selecting previously unselected package g++-13. 445s Preparing to unpack .../23-g++-13_13.2.0-23ubuntu4_ppc64el.deb ... 445s Unpacking g++-13 (13.2.0-23ubuntu4) ... 445s Selecting previously unselected package g++-powerpc64le-linux-gnu. 445s Preparing to unpack .../24-g++-powerpc64le-linux-gnu_4%3a13.2.0-7ubuntu1_ppc64el.deb ... 445s Unpacking g++-powerpc64le-linux-gnu (4:13.2.0-7ubuntu1) ... 445s Selecting previously unselected package g++. 445s Preparing to unpack .../25-g++_4%3a13.2.0-7ubuntu1_ppc64el.deb ... 445s Unpacking g++ (4:13.2.0-7ubuntu1) ... 445s Selecting previously unselected package build-essential. 445s Preparing to unpack .../26-build-essential_12.10ubuntu1_ppc64el.deb ... 445s Unpacking build-essential (12.10ubuntu1) ... 445s Selecting previously unselected package libblas3:ppc64el. 445s Preparing to unpack .../27-libblas3_3.12.0-3build1_ppc64el.deb ... 445s Unpacking libblas3:ppc64el (3.12.0-3build1) ... 445s Selecting previously unselected package libgfortran5:ppc64el. 445s Preparing to unpack .../28-libgfortran5_14.1.0-1ubuntu1_ppc64el.deb ... 445s Unpacking libgfortran5:ppc64el (14.1.0-1ubuntu1) ... 445s Selecting previously unselected package liblapack3:ppc64el. 445s Preparing to unpack .../29-liblapack3_3.12.0-3build1_ppc64el.deb ... 445s Unpacking liblapack3:ppc64el (3.12.0-3build1) ... 445s Selecting previously unselected package libslow5-0t64:ppc64el. 445s Preparing to unpack .../30-libslow5-0t64_0.7.0+dfsg-2.1build1_ppc64el.deb ... 445s Unpacking libslow5-0t64:ppc64el (0.7.0+dfsg-2.1build1) ... 445s Selecting previously unselected package libslow5-dev:ppc64el. 445s Preparing to unpack .../31-libslow5-dev_0.7.0+dfsg-2.1build1_ppc64el.deb ... 445s Unpacking libslow5-dev:ppc64el (0.7.0+dfsg-2.1build1) ... 445s Selecting previously unselected package libstreamvbyte0:ppc64el. 445s Preparing to unpack .../32-libstreamvbyte0_0.4.1-4ubuntu1_ppc64el.deb ... 445s Unpacking libstreamvbyte0:ppc64el (0.4.1-4ubuntu1) ... 445s Selecting previously unselected package libstreamvbyte-dev:ppc64el. 445s Preparing to unpack .../33-libstreamvbyte-dev_0.4.1-4ubuntu1_ppc64el.deb ... 445s Unpacking libstreamvbyte-dev:ppc64el (0.4.1-4ubuntu1) ... 445s Selecting previously unselected package python3-numpy. 445s Preparing to unpack .../34-python3-numpy_1%3a1.26.4+ds-10_ppc64el.deb ... 445s Unpacking python3-numpy (1:1.26.4+ds-10) ... 445s Selecting previously unselected package python3-slow5. 445s Preparing to unpack .../35-python3-slow5_0.7.0+dfsg-2.1build1_ppc64el.deb ... 445s Unpacking python3-slow5 (0.7.0+dfsg-2.1build1) ... 446s Selecting previously unselected package zlib1g-dev:ppc64el. 446s Preparing to unpack .../36-zlib1g-dev_1%3a1.3.dfsg-3.1ubuntu2_ppc64el.deb ... 446s Unpacking zlib1g-dev:ppc64el (1:1.3.dfsg-3.1ubuntu2) ... 446s Selecting previously unselected package autopkgtest-satdep. 446s Preparing to unpack .../37-2-autopkgtest-satdep.deb ... 446s Unpacking autopkgtest-satdep (0) ... 446s Setting up libstreamvbyte0:ppc64el (0.4.1-4ubuntu1) ... 446s Setting up libgomp1:ppc64el (14.1.0-1ubuntu1) ... 446s Setting up libblas3:ppc64el (3.12.0-3build1) ... 446s 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 446s Setting up gcc-13-base:ppc64el (13.2.0-23ubuntu4) ... 446s Setting up libstreamvbyte-dev:ppc64el (0.4.1-4ubuntu1) ... 446s Setting up libquadmath0:ppc64el (14.1.0-1ubuntu1) ... 446s Setting up libmpc3:ppc64el (1.3.1-1build1) ... 446s Setting up libatomic1:ppc64el (14.1.0-1ubuntu1) ... 446s Setting up libslow5-0t64:ppc64el (0.7.0+dfsg-2.1build1) ... 446s Setting up libgfortran5:ppc64el (14.1.0-1ubuntu1) ... 446s Setting up libubsan1:ppc64el (14.1.0-1ubuntu1) ... 446s Setting up zlib1g-dev:ppc64el (1:1.3.dfsg-3.1ubuntu2) ... 446s Setting up libasan8:ppc64el (14.1.0-1ubuntu1) ... 446s Setting up libtsan2:ppc64el (14.1.0-1ubuntu1) ... 446s Setting up libisl23:ppc64el (0.26-3build1) ... 446s Setting up cpp-13-powerpc64le-linux-gnu (13.2.0-23ubuntu4) ... 446s Setting up libcc1-0:ppc64el (14.1.0-1ubuntu1) ... 446s Setting up liblsan0:ppc64el (14.1.0-1ubuntu1) ... 446s Setting up libitm1:ppc64el (14.1.0-1ubuntu1) ... 446s Setting up cpp-powerpc64le-linux-gnu (4:13.2.0-7ubuntu1) ... 446s Setting up liblapack3:ppc64el (3.12.0-3build1) ... 446s 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 446s Setting up cpp-13 (13.2.0-23ubuntu4) ... 446s Setting up libslow5-dev:ppc64el (0.7.0+dfsg-2.1build1) ... 446s Setting up python3-numpy (1:1.26.4+ds-10) ... 448s Setting up libgcc-13-dev:ppc64el (13.2.0-23ubuntu4) ... 448s Setting up cpp (4:13.2.0-7ubuntu1) ... 448s Setting up libstdc++-13-dev:ppc64el (13.2.0-23ubuntu4) ... 448s Setting up gcc-13-powerpc64le-linux-gnu (13.2.0-23ubuntu4) ... 448s Setting up gcc-13 (13.2.0-23ubuntu4) ... 448s Setting up python3-slow5 (0.7.0+dfsg-2.1build1) ... 448s Setting up g++-13-powerpc64le-linux-gnu (13.2.0-23ubuntu4) ... 448s Setting up gcc-powerpc64le-linux-gnu (4:13.2.0-7ubuntu1) ... 448s Setting up g++-powerpc64le-linux-gnu (4:13.2.0-7ubuntu1) ... 448s Setting up g++-13 (13.2.0-23ubuntu4) ... 448s Setting up gcc (4:13.2.0-7ubuntu1) ... 448s Setting up g++ (4:13.2.0-7ubuntu1) ... 448s update-alternatives: using /usr/bin/g++ to provide /usr/bin/c++ (c++) in auto mode 448s Setting up build-essential (12.10ubuntu1) ... 448s Setting up autopkgtest-satdep (0) ... 448s Processing triggers for man-db (2.12.1-2) ... 449s Processing triggers for libc-bin (2.39-3.1ubuntu3) ... 451s (Reading database ... 74891 files and directories currently installed.) 451s Removing autopkgtest-satdep (0) ... 455s autopkgtest [21:56:34]: test run-pkg-test: [----------------------- 455s Checking unit_test_ascii.c 456s Done! 456s Checking unit_test_binary.c 456s Done! 456s Checking unit_test_empty.c 456s Done! 456s Checking unit_test_enum.c 456s Done! 456s Checking unit_test_helpers.c 456s Done! 456s Checking unit_test_lossless.c 456s Done! 456s Checking unit_test_press.c 456s Done! 456s Checking unit_test_two_rg.c 457s Done! 457s autopkgtest [21:56:36]: test run-pkg-test: -----------------------] 457s run-pkg-test PASS 457s autopkgtest [21:56:36]: test run-pkg-test: - - - - - - - - - - results - - - - - - - - - - 458s autopkgtest [21:56:37]: @@@@@@@@@@@@@@@@@@@@ summary 458s run-pybinding-test PASS 458s run-pkg-test PASS 476s nova [W] Using flock in scalingstack-bos02-ppc64el 476s Creating nova instance adt-oracular-ppc64el-libslow5lib-20240712-214859-juju-7f2275-prod-proposed-migration-environment-3-8003d09c-8d0c-498d-9c2d-4b5ad4f9c7f1 from image adt/ubuntu-oracular-ppc64el-server-20240712.img (UUID 740e1066-971a-4f95-9033-0eb4cf07697e)... 476s nova [W] Using flock in scalingstack-bos02-ppc64el 476s flock: timeout while waiting to get lock 476s Creating nova instance adt-oracular-ppc64el-libslow5lib-20240712-214859-juju-7f2275-prod-proposed-migration-environment-3-8003d09c-8d0c-498d-9c2d-4b5ad4f9c7f1 from image adt/ubuntu-oracular-ppc64el-server-20240712.img (UUID 740e1066-971a-4f95-9033-0eb4cf07697e)...