Multiple platform build/check report for BioC 3.20 - CHECK results for HTSeqGenie on nebbiolo2

Hostname	OS	Arch (*)	R version	Installed pkgs
nebbiolo2	Linux (Ubuntu 22.04.3 LTS)	x86_64	4.4.1 (2024-06-14) -- "Race for Your Life"	4703
palomino8	Windows Server 2022 Datacenter	x64	4.4.1 (2024-06-14 ucrt) -- "Race for Your Life"	4440
lconway	macOS 12.7.1 Monterey	x86_64	4.4.1 (2024-06-14) -- "Race for Your Life"	4472
kjohnson3	macOS 13.6.5 Ventura	arm64	4.4.1 (2024-06-14) -- "Race for Your Life"	4420
kunpeng2	Linux (openEuler 22.03 LTS-SP1)	aarch64	4.4.1 (2024-06-14) -- "Race for Your Life"	4413
Click on any hostname to see more info about the system (e.g. compilers) () as reported by 'uname -p', except on Windows and Mac OS X*

CHECK results for HTSeqGenie on nebbiolo2

To the developers/maintainers of the HTSeqGenie package:
- Allow up to 24 hours (and sometimes 48 hours) for your latest push to git@git.bioconductor.org:packages/HTSeqGenie.git to reflect on this report. See Troubleshooting Build Report for more information.
- Use the following Renviron settings to reproduce errors and warnings.
- If 'R CMD check' started to fail recently on the Linux builder(s) over a missing dependency, add the missing dependency to 'Suggests:' in your DESCRIPTION file. See Renviron.bioc for more information.

raw results

Summary

Package: HTSeqGenie

Version: 4.35.0

Command: /home/biocbuild/bbs-3.20-bioc/R/bin/R CMD check --install=check:HTSeqGenie.install-out.txt --library=/home/biocbuild/bbs-3.20-bioc/R/site-library --timings HTSeqGenie_4.35.0.tar.gz

StartedAt: 2024-08-15 00:18:37 -0400 (Thu, 15 Aug 2024)

EndedAt: 2024-08-15 00:32:46 -0400 (Thu, 15 Aug 2024)

EllapsedTime: 849.5 seconds

RetCode: 0

Status: OK

CheckDir: HTSeqGenie.Rcheck

Warnings: 0

Command output

##############################################################################
##############################################################################
###
### Running command:
###
###   /home/biocbuild/bbs-3.20-bioc/R/bin/R CMD check --install=check:HTSeqGenie.install-out.txt --library=/home/biocbuild/bbs-3.20-bioc/R/site-library --timings HTSeqGenie_4.35.0.tar.gz
###
##############################################################################
##############################################################################


* using log directory ‘/home/biocbuild/bbs-3.20-bioc/meat/HTSeqGenie.Rcheck’
* using R version 4.4.1 (2024-06-14)
* using platform: x86_64-pc-linux-gnu
* R was compiled by
    gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0
    GNU Fortran (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0
* running under: Ubuntu 22.04.4 LTS
* using session charset: UTF-8
* checking for file ‘HTSeqGenie/DESCRIPTION’ ... OK
* checking extension type ... Package
* this is package ‘HTSeqGenie’ version ‘4.35.0’
* checking package namespace information ... OK
* checking package dependencies ... OK
* checking if this is a source package ... OK
* checking if there is a namespace ... OK
* checking for hidden files and directories ... NOTE
Found the following hidden files and directories:
  .BBSoptions
These were most likely included in error. See section ‘Package
structure’ in the ‘Writing R Extensions’ manual.
* checking for portable file names ... OK
* checking for sufficient/correct file permissions ... OK
* checking whether package ‘HTSeqGenie’ can be installed ... OK
* checking installed package size ... OK
* checking package directory ... OK
* checking ‘build’ directory ... OK
* checking DESCRIPTION meta-information ... NOTE
Malformed Title field: should not end in a period.
* checking top-level files ... OK
* checking for left-over files ... OK
* checking index information ... OK
* checking package subdirectories ... OK
* checking code files for non-ASCII characters ... OK
* checking R files for syntax errors ... OK
* checking whether the package can be loaded ... OK
* checking whether the package can be loaded with stated dependencies ... OK
* checking whether the package can be unloaded cleanly ... OK
* checking whether the namespace can be loaded with stated dependencies ... OK
* checking whether the namespace can be unloaded cleanly ... OK
* checking loading without being on the library search path ... OK
* checking whether startup messages can be suppressed ... OK
* checking dependencies in R code ... NOTE
Unexported objects imported by ':::' calls:
  ‘ShortRead:::.set_omp_threads’ ‘gmapR:::..gsnap’ ‘gmapR:::GeneGenome’
  ‘gmapR:::checkPackageInstalled’ ‘gmapR:::getDefaultGmapGenomePath’
  ‘gmapR:::getGeneRoi’ ‘gmapR:::subsetRegion’ ‘parallel:::mckill’
  See the note in ?`:::` about the use of this operator.
* checking S3 generic/method consistency ... OK
* checking replacement functions ... OK
* checking foreign function calls ... NOTE
Foreign function call to a different package:
  .Call(ShortRead:::.set_omp_threads, ...)
See chapter ‘System and foreign language interfaces’ in the ‘Writing R
Extensions’ manual.
* checking R code for possible problems ... NOTE
.makePreprocessAlignPlots: no visible binding for global variable
  ‘data’
.plot.in.out.min.max.readlength: no visible global function definition
  for ‘median’
FastQStreamer.init: no visible binding for '<<-' assignment to
  ‘FastQStreamer.lfqs’
FastQStreamer.init: no visible binding for '<<-' assignment to
  ‘FastQStreamer.chunkid’
FastQStreamer.init: no visible binding for '<<-' assignment to
  ‘FastQStreamer.subsampling_filter’
FastQStreamer.init: no visible binding for '<<-' assignment to
  ‘FastQStreamer.max_nbchunks’
addHandler: no visible binding for '<<-' assignment to
  ‘logging.handlers’
addHandler: no visible binding for global variable ‘logging.handlers’
addHandler: no visible binding for '<<-' assignment to ‘logging.file’
buildAnyFastaGenome: no visible global function definition for ‘getSeq’
buildGenomicFeaturesFromTxDb: no visible global function definition for
  ‘gaps’
buildGenomicFeaturesFromTxDb: no visible global function definition for
  ‘ranges’
buildTP53FastaGenome: no visible global function definition for
  ‘getSeq’
buildTallyParam: no visible global function definition for ‘seqinfo’
computeCoverage: no visible global function definition for ‘resize’
computeCoverage: no visible global function definition for ‘coverage’
estimateCutoffs : <anonymous>: no visible binding for global variable
  ‘quantile’
getGenomeSegments: no visible global function definition for ‘seqinfo’
hashVariants: no visible global function definition for ‘ranges’
isAboveQualityThresh: no visible global function definition for ‘Views’
isAboveQualityThresh: no visible global function definition for
  ‘viewMeans’
listIterator.init: no visible binding for '<<-' assignment to
  ‘listIterator.n’
listIterator.init: no visible binding for '<<-' assignment to
  ‘listIterator.x’
logReset: no visible binding for '<<-' assignment to ‘logging.handlers’
logReset: no visible binding for '<<-' assignment to ‘logging.loglevel’
logReset: no visible binding for '<<-' assignment to ‘logging.file’
loglevel: no visible binding for global variable ‘logging.loglevel’
loglevel: no visible binding for global variable ‘logging.handlers’
processChunks : tracefun: no visible binding for global variable
  ‘sjobs’
processChunks : tracefun: no visible binding for global variable
  ‘chunkid’
setLevel: no visible binding for '<<-' assignment to ‘logging.loglevel’
statCountFeatures: no visible global function definition for ‘quantile’
truncateReads: no visible global function definition for ‘subseq’
vcfStat: no visible global function definition for ‘quantile’
writeToFile: no visible binding for global variable ‘logging.file’
Undefined global functions or variables:
  Views chunkid coverage data gaps getSeq logging.file logging.handlers
  logging.loglevel median quantile ranges resize seqinfo sjobs subseq
  viewMeans
Consider adding
  importFrom("stats", "median", "quantile")
  importFrom("utils", "data")
to your NAMESPACE file.
* checking Rd files ... NOTE
checkRd: (-1) calculateTargetLengths.Rd:17: Lost braces; missing escapes or markup?
    17 | Target length table and writes two files in {save_dir}/reports/images/TargetLenghts.[pdf|png]"
       |                                             ^
checkRd: (-1) initLog.Rd:18: Lost braces; missing escapes or markup?
    18 | Setup logging file in {save_dir}/progress.log
       |                       ^
* checking Rd metadata ... OK
* checking Rd cross-references ... OK
* checking for missing documentation entries ... OK
* checking for code/documentation mismatches ... OK
* checking Rd \usage sections ... NOTE
Documented arguments not in \usage in Rd file 'findVariantFile.Rd':
  ‘dir_path’

Documented arguments not in \usage in Rd file 'logdebug.Rd':
  ‘...’

Documented arguments not in \usage in Rd file 'logerror.Rd':
  ‘...’

Documented arguments not in \usage in Rd file 'loginfo.Rd':
  ‘...’

Documented arguments not in \usage in Rd file 'logwarn.Rd':
  ‘...’

Functions with \usage entries need to have the appropriate \alias
entries, and all their arguments documented.
The \usage entries must correspond to syntactically valid R code.
See chapter ‘Writing R documentation files’ in the ‘Writing R
Extensions’ manual.
* checking Rd contents ... OK
* checking for unstated dependencies in examples ... OK
* checking files in ‘vignettes’ ... OK
* checking examples ... OK
* checking for unstated dependencies in ‘tests’ ... OK
* checking tests ...
  Running ‘doRUnit.R’
 OK
* checking for unstated dependencies in vignettes ... OK
* checking package vignettes ... OK
* checking re-building of vignette outputs ... OK
* checking PDF version of manual ... OK
* DONE

Status: 7 NOTEs
See
  ‘/home/biocbuild/bbs-3.20-bioc/meat/HTSeqGenie.Rcheck/00check.log’
for details.

Installation output

HTSeqGenie.Rcheck/00install.out

##############################################################################
##############################################################################
###
### Running command:
###
###   /home/biocbuild/bbs-3.20-bioc/R/bin/R CMD INSTALL HTSeqGenie
###
##############################################################################
##############################################################################


* installing to library ‘/home/biocbuild/bbs-3.20-bioc/R/site-library’
* installing *source* package ‘HTSeqGenie’ ...
** using staged installation
** R
** inst
** byte-compile and prepare package for lazy loading
** help
*** installing help indices
** building package indices
** installing vignettes
** testing if installed package can be loaded from temporary location
** testing if installed package can be loaded from final location
** testing if installed package keeps a record of temporary installation path
* DONE (HTSeqGenie)

Tests output

HTSeqGenie.Rcheck/tests/doRUnit.Rout


R version 4.4.1 (2024-06-14) -- "Race for Your Life"
Copyright (C) 2024 The R Foundation for Statistical Computing
Platform: x86_64-pc-linux-gnu

R is free software and comes with ABSOLUTELY NO WARRANTY.
You are welcome to redistribute it under certain conditions.
Type 'license()' or 'licence()' for distribution details.

R is a collaborative project with many contributors.
Type 'contributors()' for more information and
'citation()' on how to cite R or R packages in publications.

Type 'demo()' for some demos, 'help()' for on-line help, or
'help.start()' for an HTML browser interface to help.
Type 'q()' to quit R.

> library("HTSeqGenie")
Loading required package: gmapR
Loading required package: GenomeInfoDb
Loading required package: BiocGenerics

Attaching package: 'BiocGenerics'

The following objects are masked from 'package:stats':

    IQR, mad, sd, var, xtabs

The following objects are masked from 'package:base':

    Filter, Find, Map, Position, Reduce, anyDuplicated, aperm, append,
    as.data.frame, basename, cbind, colnames, dirname, do.call,
    duplicated, eval, evalq, get, grep, grepl, intersect, is.unsorted,
    lapply, mapply, match, mget, order, paste, pmax, pmax.int, pmin,
    pmin.int, rank, rbind, rownames, sapply, setdiff, table, tapply,
    union, unique, unsplit, which.max, which.min

Loading required package: S4Vectors
Loading required package: stats4

Attaching package: 'S4Vectors'

The following object is masked from 'package:utils':

    findMatches

The following objects are masked from 'package:base':

    I, expand.grid, unname

Loading required package: IRanges
Loading required package: GenomicRanges
Loading required package: Rsamtools
Loading required package: Biostrings
Loading required package: XVector

Attaching package: 'Biostrings'

The following object is masked from 'package:base':

    strsplit

Loading required package: ShortRead
Loading required package: BiocParallel
Loading required package: GenomicAlignments
Loading required package: SummarizedExperiment
Loading required package: MatrixGenerics
Loading required package: matrixStats

Attaching package: 'MatrixGenerics'

The following objects are masked from 'package:matrixStats':

    colAlls, colAnyNAs, colAnys, colAvgsPerRowSet, colCollapse,
    colCounts, colCummaxs, colCummins, colCumprods, colCumsums,
    colDiffs, colIQRDiffs, colIQRs, colLogSumExps, colMadDiffs,
    colMads, colMaxs, colMeans2, colMedians, colMins, colOrderStats,
    colProds, colQuantiles, colRanges, colRanks, colSdDiffs, colSds,
    colSums2, colTabulates, colVarDiffs, colVars, colWeightedMads,
    colWeightedMeans, colWeightedMedians, colWeightedSds,
    colWeightedVars, rowAlls, rowAnyNAs, rowAnys, rowAvgsPerColSet,
    rowCollapse, rowCounts, rowCummaxs, rowCummins, rowCumprods,
    rowCumsums, rowDiffs, rowIQRDiffs, rowIQRs, rowLogSumExps,
    rowMadDiffs, rowMads, rowMaxs, rowMeans2, rowMedians, rowMins,
    rowOrderStats, rowProds, rowQuantiles, rowRanges, rowRanks,
    rowSdDiffs, rowSds, rowSums2, rowTabulates, rowVarDiffs, rowVars,
    rowWeightedMads, rowWeightedMeans, rowWeightedMedians,
    rowWeightedSds, rowWeightedVars

Loading required package: Biobase
Welcome to Bioconductor

    Vignettes contain introductory material; view with
    'browseVignettes()'. To cite Bioconductor, see
    'citation("Biobase")', and for packages 'citation("pkgname")'.


Attaching package: 'Biobase'

The following object is masked from 'package:MatrixGenerics':

    rowMedians

The following objects are masked from 'package:matrixStats':

    anyMissing, rowMedians

Loading required package: VariantAnnotation

Attaching package: 'VariantAnnotation'

The following object is masked from 'package:base':

    tabulate

> 
> source(getPackageFile("unitTests/runTests.R"))
Loading required package: GenomicFeatures
Loading required package: AnnotationDbi
did not source anything in dirname= ./R 


Executing test function test.alignReads  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:24:36.827194 INFO::preprocessReads.R/preprocessReads: starting...
2024-08-15 00:24:36.836116 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:24:36.839754 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-08-15 00:24:36.842047 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:24:39.835217 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:24:39.836666 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/chunks/chunk_000001/logs/progress.log
2024-08-15 00:24:42.572791 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.046 minutes
2024-08-15 00:24:42.57431 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/chunks/chunk_000002/logs/progress.log
2024-08-15 00:24:45.313692 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.046 minutes
2024-08-15 00:24:45.315065 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/chunks/chunk_000003/logs/progress.log
2024-08-15 00:24:48.035284 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.045 minutes
2024-08-15 00:24:48.065711 DEBUG::tools.R/processChunks: done
2024-08-15 00:24:48.069491 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-08-15 00:24:48.071679 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/results/test_pe.adapter_contaminated_1.RData
2024-08-15 00:24:48.074471 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-08-15 00:24:48.076076 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/results/test_pe.adapter_contaminated_2.RData
2024-08-15 00:24:48.085195 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=26 highqual_reads=25 adapter_contam=1 read_length=75 rRNA_contam_reads=0 processed_reads=25 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-08-15 00:24:48.087363 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/results/test_pe.summary_preprocess.tab
2024-08-15 00:24:48.090898 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/bams/processed.aligner_input_1.fastq ...
2024-08-15 00:24:48.095297 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/bams/processed.aligner_input_2.fastq ...
2024-08-15 00:24:48.098328 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/reports/shortReadReport_1 ...
2024-08-15 00:24:49.425129 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/reports/shortReadReport_2 ...
2024-08-15 00:24:50.470366 INFO::preprocessReads.R/preprocessReads: done
2024-08-15 00:24:50.544161 INFO::alignReads.R/alignReads: starting alignment...
2024-08-15 00:24:50.551048 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:24:53.507521 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:24:53.509167 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/chunks/chunk_000001/logs/progress.log
2024-08-15 00:24:56.342833 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.047 minutes
2024-08-15 00:24:56.344608 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/chunks/chunk_000002/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-08-15 00:24:58.985512 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.044 minutes
2024-08-15 00:24:58.987736 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/chunks/chunk_000003/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-08-15 00:25:01.57011 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-08-15 00:25:01.573919 DEBUG::tools.R/processChunks: done
2024-08-15 00:25:01.576146 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-08-15 00:25:01.797507 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-08-15 00:25:01.80592 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/results/test_pe.summary_alignment.tab
2024-08-15 00:25:01.81275 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/results/test_pe.summary_analyzed_bamstats.tab
2024-08-15 00:25:01.814413 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-08-15 00:25:02.056835 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.alignReads.1367d94794fbd/results/test_pe.summary_target_lengths.tab
2024-08-15 00:25:02.103832 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-08-15 00:25:02.104815 INFO::alignReads.R/alignReads: done
 done successfully.



Executing test function test.alignReads.sparsechunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:25:02.358234 INFO::preprocessReads.R/preprocessReads: starting...
2024-08-15 00:25:02.361722 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:25:02.437006 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 2 , totnbreads= 26 )
2024-08-15 00:25:02.442208 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:25:02.445338 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-08-15 00:25:02.447354 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:25:05.504183 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:25:05.505668 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpBtZQPF/test.alignReads.sparsechunks.1367d9772557a6/chunks/chunk_000001/logs/progress.log
2024-08-15 00:25:08.222553 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.045 minutes
2024-08-15 00:25:08.224626 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpBtZQPF/test.alignReads.sparsechunks.1367d9772557a6/chunks/chunk_000002/logs/progress.log
2024-08-15 00:25:10.914838 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.045 minutes
2024-08-15 00:25:10.916727 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpBtZQPF/test.alignReads.sparsechunks.1367d9772557a6/chunks/chunk_000003/logs/progress.log
2024-08-15 00:25:13.68219 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.046 minutes
2024-08-15 00:25:13.683698 DEBUG::tools.R/processChunks: starting chunkid= 4 ; see logfile= /tmp/RtmpBtZQPF/test.alignReads.sparsechunks.1367d9772557a6/chunks/chunk_000004/logs/progress.log
2024-08-15 00:25:16.393564 DEBUG::tools.R/processChunks: done with chunkid= 4 ; elapsed.time= 0.045 minutes
2024-08-15 00:25:16.422562 DEBUG::tools.R/processChunks: done
2024-08-15 00:25:16.426073 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-08-15 00:25:16.428407 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.alignReads.sparsechunks.1367d9772557a6/results/test_pe.adapter_contaminated_1.RData
2024-08-15 00:25:16.431312 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-08-15 00:25:16.432919 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.alignReads.sparsechunks.1367d9772557a6/results/test_pe.adapter_contaminated_2.RData
2024-08-15 00:25:16.442785 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=2 highqual_reads=1 adapter_contam=0 read_length=75 rRNA_contam_reads=0 processed_reads=1 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-08-15 00:25:16.444929 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.alignReads.sparsechunks.1367d9772557a6/results/test_pe.summary_preprocess.tab
2024-08-15 00:25:16.448409 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpBtZQPF/test.alignReads.sparsechunks.1367d9772557a6/bams/processed.aligner_input_1.fastq ...
2024-08-15 00:25:16.452292 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpBtZQPF/test.alignReads.sparsechunks.1367d9772557a6/bams/processed.aligner_input_2.fastq ...
2024-08-15 00:25:16.455039 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpBtZQPF/test.alignReads.sparsechunks.1367d9772557a6/reports/shortReadReport_1 ...
2024-08-15 00:25:17.697724 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpBtZQPF/test.alignReads.sparsechunks.1367d9772557a6/reports/shortReadReport_2 ...
2024-08-15 00:25:18.663013 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.alignReadsOneSingleEnd  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:25:18.808387 INFO::alignReads.R/alignReadsChunk: running gsnap...
2024-08-15 00:25:18.812799 INFO::alignReads.R/alignReadsChunk: calling gsnap (from gmapR) with args= -D /home/biocbuild/.local/share/gmap -t 1 -d TP53_demo_3.2.2 --quality-protocol=illumina  -A sam --read-group-id=test_se -m 0 --split-output /tmp/RtmpBtZQPF/test.alignReadsOneSingleEnd.1367d9190e70ca/bams/test.alignReads /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq 2>&1
2024-08-15 00:25:19.012275 INFO::alignReads.R/createSummaryAlignment: counting unique bam reads...
2024-08-15 00:25:19.103221 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.alignReadsOneSingleEnd.1367d9190e70ca/results/test.alignReads.summary_alignment.tab
2024-08-15 00:25:19.146916 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.alignReadsOneSingleEnd.1367d9190e70ca/results/test.alignReads.summary_analyzed_bamstats.tab
2024-08-15 00:25:19.148491 INFO::alignReads.R/alignReadsChunk: done
 done successfully.



Executing test function test.annotateVariants  ... Timing stopped at: 0 0.001 0.002
Error in DEACTIVATED("Skipped annotateVariants() test") : 
  Skipped annotateVariants() test
In addition: There were 11 warnings (use warnings() to see them)
 done successfully.



Executing test function test.callVariantsVariantTools.genotype  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:25:19.444269 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.genotype.1367d9690ad102/results/test_pe.coverage.RData
2024-08-15 00:25:19.446102 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpBtZQPF/test.genotype.1367d9690ad102/results/test_pe.coverage.bw
2024-08-15 00:25:19.555963 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.genotype.1367d9690ad102/results/test_pe.summary_coverage.tab
2024-08-15 00:25:19.557703 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-08-15 00:25:29.610253 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-08-15 00:25:29.6932 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-08-15 00:25:29.709575 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-08-15 00:25:29.71108 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.genotype.1367d9690ad102/results/test_pe.raw_variants.RData
2024-08-15 00:25:29.713461 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.genotype.1367d9690ad102/results/test_pe.filtered_variants.RData
2024-08-15 00:25:29.714803 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-08-15 00:25:29.715965 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-08-15 00:25:30.11295 INFO::analyzeVariants.R/writeVCF: ...done
2024-08-15 00:25:30.11424 INFO::analyzeVariants.R/.callGenotypes: calling genotypes...
2024-08-15 00:26:26.2381 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-08-15 00:26:26.681836 INFO::analyzeVariants.R/writeVCF: ...done
2024-08-15 00:26:26.682814 INFO::analyzeVariants.R/.callGenotypes: done
[W::bcf_hdr_check_sanity] PL should be declared as Number=G
 done successfully.



Executing test function test.wrap.callVariants  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:26:27.129649 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-08-15 00:26:37.314613 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-08-15 00:26:37.387917 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-08-15 00:26:37.403632 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-08-15 00:26:37.404971 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.wrap.callVariants.1367d93f99b1b/results/test_pe.raw_variants.RData
2024-08-15 00:26:37.407276 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.wrap.callVariants.1367d93f99b1b/results/test_pe.filtered_variants.RData
2024-08-15 00:26:37.408537 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.filters  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:26:37.547194 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-08-15 00:26:47.60494 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-08-15 00:26:47.660202 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-08-15 00:26:47.676976 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-08-15 00:26:47.678441 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.wrap.callVariants.filters.1367d93757062f/results/test_pe.raw_variants.RData
2024-08-15 00:26:47.680829 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.wrap.callVariants.filters.1367d93757062f/results/test_pe.filtered_variants.RData
2024-08-15 00:26:47.682081 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-08-15 00:26:47.683521 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-08-15 00:26:57.832813 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-08-15 00:26:57.869952 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-08-15 00:26:57.885736 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-08-15 00:26:57.887063 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.wrap.callVariants.filters.1367d93757062f/results/test_pe.raw_variants.RData
2024-08-15 00:26:57.889498 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.wrap.callVariants.filters.1367d93757062f/results/test_pe.filtered_variants.RData
2024-08-15 00:26:57.891412 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.which  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:26:59.495906 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-08-15 00:26:59.497271 INFO::analyzeVariants.R/buildTallyParam: restricting variant calls using 'which'
2024-08-15 00:27:02.21541 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-08-15 00:27:02.289506 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-08-15 00:27:02.305663 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-08-15 00:27:02.307122 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.wrap.callVariants.which.1367d97bee73c9/results/test_pe.raw_variants.RData
2024-08-15 00:27:02.308745 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.wrap.callVariants.which.1367d97bee73c9/results/test_pe.filtered_variants.RData
2024-08-15 00:27:02.309982 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.writeVCF.NULL  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:27:02.436249 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-08-15 00:27:02.437557 INFO::analyzeVariants.R/writeVCF: ...done
 done successfully.



Executing test function test.writeVCF.vcfStat  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:27:02.624674 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-08-15 00:27:02.814758 INFO::analyzeVariants.R/writeVCF: ...done
 done successfully.



Executing test function test.isFirstFragment  ...  done successfully.



Executing test function test.buildCountsGRangesList  ...   403 genes were dropped because they have exons located on both strands
  of the same reference sequence or on more than one reference sequence,
  so cannot be represented by a single genomic range.
  Use 'single.strand.genes.only=FALSE' to get all the genes in a
  GRangesList object, or use suppressMessages() to suppress this message.
 done successfully.



Executing test function test.generateSingleGeneDERs  ...  done successfully.



Executing test function test.computeCoverage  ...  done successfully.



Executing test function test.isSparse  ...  done successfully.



Executing test function test.mergeCoverage  ... 2024-08-15 00:27:57.328099 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/mwthyxpc/merged/results/bla.coverage.RData
2024-08-15 00:27:57.330934 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpBtZQPF/mwthyxpc/merged/results/bla.coverage.bw
2024-08-15 00:27:57.404151 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/mwthyxpc/merged/results/bla.summary_coverage.tab
 done successfully.



Executing test function test.mergeCoverage.sparse  ... 2024-08-15 00:27:58.52572 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/uwbpveyc/merged/results/bla.coverage.RData
2024-08-15 00:27:58.527221 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpBtZQPF/uwbpveyc/merged/results/bla.coverage.bw
2024-08-15 00:27:58.538427 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/uwbpveyc/merged/results/bla.summary_coverage.tab
 done successfully.



Executing test function test.checkConfig.analyzeVariants  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
 done successfully.



Executing test function test.findTemplate  ...  done successfully.



Executing test function test.checkConfig  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
 done successfully.



Executing test function test.checkConfig.alignReads  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
 done successfully.



Executing test function test.getConfig  ...  done successfully.



Executing test function test.loadConfig  ...  done successfully.



Executing test function test.parseDCF  ...  done successfully.



Executing test function test.updateConfig  ...  done successfully.



Executing test function test.getAdapterSeqs  ...  done successfully.



Executing test function test.isAdapter  ...  done successfully.



Executing test function test.isAdapter3.primeEnd  ...  done successfully.



Executing test function test.detectRRNA  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:27:59.702419 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-08-15 00:27:59.703535 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmpBtZQPF/test.detectRRNA.1367d95b46f07/bams/rRNA_contam/input1.fastq
2024-08-15 00:27:59.706581 INFO::alignReads.R/alignReadsChunk: calling gsnap (from gmapR) with args= -t 0 -D /home/biocbuild/.local/share/gmap -n 1 -d TP53_demo_3.2.2 -A sam -B 2 --pairmax-rna=200000 --split-output /tmp/RtmpBtZQPF/test.detectRRNA.1367d95b46f07/bams/rRNA_contam/test_se /tmp/RtmpBtZQPF/test.detectRRNA.1367d95b46f07/bams/rRNA_contam/input1.fastq 2>&1
2024-08-15 00:27:59.829384 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-08-15 00:27:59.830302 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.detectRRNA.paired_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:27:59.971172 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-08-15 00:27:59.972154 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmpBtZQPF/test.detectRRNA.paired_end.1367d95144ad88/bams/rRNA_contam/input1.fastq
2024-08-15 00:27:59.973598 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmpBtZQPF/test.detectRRNA.paired_end.1367d95144ad88/bams/rRNA_contam/input2.fastq
2024-08-15 00:27:59.975703 INFO::alignReads.R/alignReadsChunk: calling gsnap (from gmapR) with args= -t 0 -D /home/biocbuild/.local/share/gmap -n 1 -d TP53_demo_3.2.2 -A sam -B 2 --pairmax-rna=200000 --split-output /tmp/RtmpBtZQPF/test.detectRRNA.paired_end.1367d95144ad88/bams/rRNA_contam/test_pe /tmp/RtmpBtZQPF/test.detectRRNA.paired_end.1367d95144ad88/bams/rRNA_contam/input1.fastq -a paired /tmp/RtmpBtZQPF/test.detectRRNA.paired_end.1367d95144ad88/bams/rRNA_contam/input2.fastq 2>&1
2024-08-15 00:28:00.189503 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-08-15 00:28:00.190443 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.getRRNAIds  ... 2024-08-15 00:28:00.208023 INFO::alignReads.R/alignReadsChunk: calling gsnap (from gmapR) with args= -t 0 -D /home/biocbuild/.local/share/gmap -n 1 -d TP53_demo_3.2.2 -A sam -B 2 --pairmax-rna=200000 --split-output /tmp/RtmpBtZQPF/test_get_rRNA_idssvwpugbi/test_pe /tmp/RtmpBtZQPF/test_get_rRNA_idssvwpugbi/1.fastq -a paired /tmp/RtmpBtZQPF/test_get_rRNA_idssvwpugbi/2.fastq 2>&1
 done successfully.



Executing test function test.getRRNAIds_random  ... 2024-08-15 00:28:00.44024 INFO::alignReads.R/alignReadsChunk: calling gsnap (from gmapR) with args= -t 0 -D /home/biocbuild/.local/share/gmap -n 1 -d TP53_demo_3.2.2 -A sam -B 2 --pairmax-rna=200000 --split-output /tmp/RtmpBtZQPF/test_get_rRNAIds_randomgoipmfcj/test_pe /tmp/RtmpBtZQPF/test_get_rRNAIds_randomgoipmfcj/1.fastq 2>&1
 done successfully.



Executing test function test.filterByLength  ... 2024-08-15 00:28:00.629637 INFO::filterQuality.R/filterQuality: filterByLength...
2024-08-15 00:28:00.631068 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 0.5
2024-08-15 00:28:00.63192 INFO::filterQuality.R/filterByLength: done
2024-08-15 00:28:00.678146 INFO::filterQuality.R/filterQuality: filterByLength...
2024-08-15 00:28:00.67913 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 1
2024-08-15 00:28:00.679919 INFO::filterQuality.R/filterByLength: done
 done successfully.



Executing test function test.isAboveQualityThresh  ...  done successfully.



Executing test function test.trimTailsByQuality  ... 2024-08-15 00:28:00.727414 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-08-15 00:28:00.736129 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-08-15 00:28:00.737323 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-08-15 00:28:00.742273 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-08-15 00:28:00.743334 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-08-15 00:28:00.747873 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-08-15 00:28:00.7488 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-08-15 00:28:00.7532 INFO::preprocessReads.R/preprocessReadsChunk: done
 done successfully.



Executing test function test.callVariantsGATK  ... Timing stopped at: 0 0 0
Error in DEACTIVATED("callVariantsGATK() tests need gatk.path option set") : 
  callVariantsGATK() tests need gatk.path option set
In addition: There were 50 or more warnings (use warnings() to see the first 50)
 done successfully.



Executing test function test.callVariantsGATK.withFiltering  ... Timing stopped at: 0 0 0
Error in DEACTIVATED("callVariantsGATK() tests need gatk.path option set") : 
  callVariantsGATK() tests need gatk.path option set
 done successfully.



Executing test function test.checkGATKJar  ... Timing stopped at: 0.001 0 0
Error in DEACTIVATED("checkGATKJar() test needs gatk.path option set") : 
  checkGATKJar() test needs gatk.path option set
 done successfully.



Executing test function test.excludeVariantsByRegion  ...  done successfully.



Executing test function test.gatk  ... Timing stopped at: 0 0 0
Error in DEACTIVATED("gatk() tests need gatk.path option set") : 
  gatk() tests need gatk.path option set
 done successfully.



Executing test function test.realignIndels  ... Timing stopped at: 0 0 0
Error in DEACTIVATED("test.realignIndels() tests need gatk.path option set") : 
  test.realignIndels() tests need gatk.path option set
 done successfully.



Executing test function test.realignIndelsGATK  ... Timing stopped at: 0 0 0
Error in DEACTIVATED("realignIndelsGATK() tests need gatk.path option set") : 
  realignIndelsGATK() tests need gatk.path option set
 done successfully.



Executing test function test.realignIndelsGATK.parallel  ... Timing stopped at: 0 0 0
Error in DEACTIVATED("realignIndelsGATK() tests need gatk.path option set") : 
  realignIndelsGATK() tests need gatk.path option set
 done successfully.



Executing test function test_zipUp  ...  done successfully.



Executing test function test.FastQStreamer.getReads.pefq  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:28:01.041193 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:28:01.043297 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



Executing test function test.FastQStreamer.getReads.pefq.subsample  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:28:01.206754 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:28:01.310719 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-08-15 00:28:01.313452 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:28:01.315557 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



Executing test function test.FastQStreamer.getReads.segz  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:28:01.532165 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/reads.fastq.gz
 done successfully.



Executing test function test.FastQStreamer.getReads.truncated  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:28:01.671559 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/truncated.fastq.gz
 done successfully.



Executing test function test.FastQStreamer.subsampler.isdeterministic  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:28:03.011066 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:28:03.055384 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-08-15 00:28:03.05779 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:28:03.05993 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:28:03.229242 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:28:03.273646 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-08-15 00:28:03.275892 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:28:03.277906 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



Executing test function test.createTmpDir  ...  done successfully.



Executing test function test.detectQualityInFASTQFile  ...  done successfully.



Executing test function test.getObjectFilename  ...  done successfully.



Executing test function test.safeUnlink  ...  done successfully.



Executing test function test.writeAudit  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
 done successfully.



Executing test function test.mergeLanes  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:28:03.866274 INFO::preprocessReads.R/preprocessReads: starting...
2024-08-15 00:28:03.871665 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:28:03.874803 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-08-15 00:28:03.876868 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:28:06.66563 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:28:06.667026 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/chunks/chunk_000001/logs/progress.log
2024-08-15 00:28:09.317528 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-08-15 00:28:09.319214 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/chunks/chunk_000002/logs/progress.log
2024-08-15 00:28:11.896196 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.043 minutes
2024-08-15 00:28:11.898046 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/chunks/chunk_000003/logs/progress.log
2024-08-15 00:28:14.633522 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.046 minutes
2024-08-15 00:28:14.691354 DEBUG::tools.R/processChunks: done
2024-08-15 00:28:14.695227 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-08-15 00:28:14.697206 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.adapter_contaminated_1.RData
2024-08-15 00:28:14.69931 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-08-15 00:28:14.700792 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.adapter_contaminated_2.RData
2024-08-15 00:28:14.7101 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=26 highqual_reads=25 adapter_contam=1 read_length=75 rRNA_contam_reads=0 processed_reads=25 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-08-15 00:28:14.712128 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.summary_preprocess.tab
2024-08-15 00:28:14.715059 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/bams/processed.aligner_input_1.fastq ...
2024-08-15 00:28:14.71906 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/bams/processed.aligner_input_2.fastq ...
2024-08-15 00:28:14.723689 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/reports/shortReadReport_1 ...
2024-08-15 00:28:16.023773 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/reports/shortReadReport_2 ...
2024-08-15 00:28:17.05647 INFO::preprocessReads.R/preprocessReads: done
2024-08-15 00:28:17.141718 INFO::alignReads.R/alignReads: starting alignment...
2024-08-15 00:28:17.14644 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:28:20.494344 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:28:20.496217 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/chunks/chunk_000001/logs/progress.log
2024-08-15 00:28:23.05652 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.043 minutes
2024-08-15 00:28:23.058833 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/chunks/chunk_000002/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-08-15 00:28:25.62474 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.043 minutes
2024-08-15 00:28:25.626484 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/chunks/chunk_000003/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-08-15 00:28:28.1678 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.042 minutes
2024-08-15 00:28:28.170158 DEBUG::tools.R/processChunks: done
2024-08-15 00:28:28.171654 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-08-15 00:28:28.350573 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-08-15 00:28:28.358029 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.summary_alignment.tab
2024-08-15 00:28:28.364232 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.summary_analyzed_bamstats.tab
2024-08-15 00:28:28.366021 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-08-15 00:28:28.597425 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.summary_target_lengths.tab
2024-08-15 00:28:28.644806 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-08-15 00:28:28.645822 INFO::alignReads.R/alignReads: done
2024-08-15 00:28:28.727419 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-08-15 00:28:28.746945 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:28:31.705984 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:28:31.707623 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/chunks/chunk_000001/logs/progress.log
2024-08-15 00:28:34.13007 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.04 minutes
2024-08-15 00:28:34.132278 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/chunks/chunk_000002/logs/progress.log
2024-08-15 00:28:36.5708 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.041 minutes
2024-08-15 00:28:36.572536 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/chunks/chunk_000003/logs/progress.log
2024-08-15 00:28:39.005615 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.041 minutes
2024-08-15 00:28:39.008004 DEBUG::tools.R/processChunks: done
2024-08-15 00:28:39.009727 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-08-15 00:28:39.023548 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.counts_exon.tab
2024-08-15 00:28:39.03521 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.counts_exon_disjoint.tab
2024-08-15 00:28:39.042533 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.counts_gene.tab
2024-08-15 00:28:39.047626 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.counts_gene_coding.tab
2024-08-15 00:28:39.052554 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.counts_gene_exonic.tab
2024-08-15 00:28:39.057628 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.counts_intergenic.tab
2024-08-15 00:28:39.067003 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.counts_intron.tab
2024-08-15 00:28:39.070401 INFO::countGenomicFeatures.R/mergeCounts: done
2024-08-15 00:28:39.075984 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.summary_counts.tab
2024-08-15 00:28:39.077643 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-08-15 00:28:39.374139 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-08-15 00:28:39.375163 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-08-15 00:28:39.451128 INFO::coverage.R/calculateCoverage: starting...
2024-08-15 00:28:39.455851 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:28:42.649971 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:28:42.65203 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/chunks/chunk_000001/logs/progress.log
2024-08-15 00:28:44.819513 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.036 minutes
2024-08-15 00:28:44.821925 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/chunks/chunk_000002/logs/progress.log
2024-08-15 00:28:46.997448 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.036 minutes
2024-08-15 00:28:46.999092 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/chunks/chunk_000003/logs/progress.log
2024-08-15 00:28:49.169122 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.036 minutes
2024-08-15 00:28:49.172282 DEBUG::tools.R/processChunks: done
2024-08-15 00:28:50.63921 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.coverage.RData
2024-08-15 00:28:50.640778 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.coverage.bw
2024-08-15 00:28:50.652726 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.summary_coverage.tab
2024-08-15 00:28:50.653969 INFO::coverage.R/calculateCoverage: done
2024-08-15 00:28:50.655875 INFO::analyzeVariants/analyzeVariants: starting ...
2024-08-15 00:28:50.735941 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-08-15 00:28:54.5524 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-08-15 00:28:54.627548 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-08-15 00:28:54.644435 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-08-15 00:28:54.645859 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.raw_variants.RData
2024-08-15 00:28:54.647449 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.filtered_variants.RData
2024-08-15 00:28:54.648625 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-08-15 00:28:54.649599 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-08-15 00:28:54.86889 INFO::analyzeVariants.R/writeVCF: ...done
2024-08-15 00:28:54.963419 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/results/test_pe.summary_variants.tab
2024-08-15 00:28:54.965385 INFO::analyzeVariants/analyzeVariants: done
2024-08-15 00:28:54.968377 INFO::Pipeline run successful.
2024-08-15 00:28:55.115785 INFO::mergeLanes.R/doMergeLanes: starting...
2024-08-15 00:28:55.121071 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-08-15 00:28:55.123407 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.adapter_contaminated_1.RData
2024-08-15 00:28:55.12633 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-08-15 00:28:55.128292 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.adapter_contaminated_2.RData
2024-08-15 00:28:55.14111 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=26 highqual_reads=25 adapter_contam=1 read_length=75 rRNA_contam_reads=0 processed_reads=25 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-08-15 00:28:55.143491 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.summary_preprocess.tab
2024-08-15 00:28:55.145822 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-08-15 00:28:55.395218 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-08-15 00:28:55.403685 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.summary_alignment.tab
2024-08-15 00:28:55.412611 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.summary_analyzed_bamstats.tab
2024-08-15 00:28:55.415016 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-08-15 00:28:55.678989 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.summary_target_lengths.tab
2024-08-15 00:28:55.732893 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-08-15 00:28:55.778721 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-08-15 00:28:55.801025 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.counts_exon.tab
2024-08-15 00:28:55.814494 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.counts_exon_disjoint.tab
2024-08-15 00:28:55.822072 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.counts_gene.tab
2024-08-15 00:28:55.827574 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.counts_gene_coding.tab
2024-08-15 00:28:55.833189 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.counts_gene_exonic.tab
2024-08-15 00:28:55.839081 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.counts_intergenic.tab
2024-08-15 00:28:55.851507 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.counts_intron.tab
2024-08-15 00:28:55.855206 INFO::countGenomicFeatures.R/mergeCounts: done
2024-08-15 00:28:55.861974 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.summary_counts.tab
2024-08-15 00:28:55.86396 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-08-15 00:28:56.16175 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-08-15 00:28:58.207165 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.coverage.RData
2024-08-15 00:28:58.209767 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.coverage.bw
2024-08-15 00:28:58.220827 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.summary_coverage.tab
2024-08-15 00:28:58.258246 INFO::analyzeVariants/analyzeVariants: starting ...
2024-08-15 00:28:58.324918 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-08-15 00:29:01.381464 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-08-15 00:29:01.449583 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-08-15 00:29:01.464845 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-08-15 00:29:01.466169 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.raw_variants.RData
2024-08-15 00:29:01.467724 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.filtered_variants.RData
2024-08-15 00:29:01.468911 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-08-15 00:29:01.469888 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-08-15 00:29:01.669555 INFO::analyzeVariants.R/writeVCF: ...done
2024-08-15 00:29:01.761038 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.mergeLanes.1367d959ad1ef8/merged/results/merged.summary_variants.tab
2024-08-15 00:29:01.763065 INFO::analyzeVariants/analyzeVariants: done
2024-08-15 00:29:01.765967 INFO::mergeLanes.R/doMergeLanes: merge lanes successful.
 done successfully.



Executing test function test.markDuplicates  ... Timing stopped at: 0 0.001 0
Error in DEACTIVATED("Skipped markDuplicates() test") : 
  Skipped markDuplicates() test
In addition: There were 28 warnings (use warnings() to see them)
 done successfully.



Executing test function test.markDuplicates_w_outfile  ... Timing stopped at: 0 0 0
Error in DEACTIVATED("Skipped markDuplicates() test") : 
  Skipped markDuplicates() test
 done successfully.



Executing test function test.preprocessReads  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:29:02.033228 INFO::preprocessReads.R/preprocessReads: starting...
2024-08-15 00:29:02.05663 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:29:02.077372 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-08-15 00:29:02.079829 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:29:06.139662 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:29:06.141138 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpBtZQPF/test.preprocessReads.1367d91833fb14/chunks/chunk_000001/logs/progress.log
2024-08-15 00:29:08.731833 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.043 minutes
2024-08-15 00:29:08.776237 DEBUG::tools.R/processChunks: done
2024-08-15 00:29:08.77856 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-08-15 00:29:08.779958 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.preprocessReads.1367d91833fb14/results/test_pe.adapter_contaminated_1.RData
2024-08-15 00:29:08.781576 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-08-15 00:29:08.782772 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.preprocessReads.1367d91833fb14/results/test_pe.adapter_contaminated_2.RData
2024-08-15 00:29:08.788608 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=26 highqual_reads=25 adapter_contam=1 read_length=75 rRNA_contam_reads=0 processed_reads=25 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-08-15 00:29:08.790276 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.preprocessReads.1367d91833fb14/results/test_pe.summary_preprocess.tab
2024-08-15 00:29:08.792188 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpBtZQPF/test.preprocessReads.1367d91833fb14/bams/processed.aligner_input_1.fastq ...
2024-08-15 00:29:08.796253 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpBtZQPF/test.preprocessReads.1367d91833fb14/bams/processed.aligner_input_2.fastq ...
2024-08-15 00:29:08.799311 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpBtZQPF/test.preprocessReads.1367d91833fb14/reports/shortReadReport_1 ...
2024-08-15 00:29:10.107156 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpBtZQPF/test.preprocessReads.1367d91833fb14/reports/shortReadReport_2 ...
2024-08-15 00:29:11.140459 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads.minichunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:29:11.369343 INFO::preprocessReads.R/preprocessReads: starting...
2024-08-15 00:29:11.375372 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:29:11.378698 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-08-15 00:29:11.381042 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:29:14.61127 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:29:14.612759 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpBtZQPF/test.preprocessReads.minichunks.1367d91991002b/chunks/chunk_000001/logs/progress.log
2024-08-15 00:29:17.23772 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-08-15 00:29:17.239314 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpBtZQPF/test.preprocessReads.minichunks.1367d91991002b/chunks/chunk_000002/logs/progress.log
2024-08-15 00:29:19.895475 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.044 minutes
2024-08-15 00:29:19.896938 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpBtZQPF/test.preprocessReads.minichunks.1367d91991002b/chunks/chunk_000003/logs/progress.log
2024-08-15 00:29:22.526561 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.044 minutes
2024-08-15 00:29:22.572822 DEBUG::tools.R/processChunks: done
2024-08-15 00:29:22.575475 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-08-15 00:29:22.576976 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.preprocessReads.minichunks.1367d91991002b/results/test_pe.adapter_contaminated_1.RData
2024-08-15 00:29:22.578874 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-08-15 00:29:22.580229 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.preprocessReads.minichunks.1367d91991002b/results/test_pe.adapter_contaminated_2.RData
2024-08-15 00:29:22.588127 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=26 highqual_reads=25 adapter_contam=1 read_length=75 rRNA_contam_reads=0 processed_reads=25 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-08-15 00:29:22.58984 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.preprocessReads.minichunks.1367d91991002b/results/test_pe.summary_preprocess.tab
2024-08-15 00:29:22.592129 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpBtZQPF/test.preprocessReads.minichunks.1367d91991002b/bams/processed.aligner_input_1.fastq ...
2024-08-15 00:29:22.59598 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpBtZQPF/test.preprocessReads.minichunks.1367d91991002b/bams/processed.aligner_input_2.fastq ...
2024-08-15 00:29:22.599002 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpBtZQPF/test.preprocessReads.minichunks.1367d91991002b/reports/shortReadReport_1 ...
2024-08-15 00:29:23.878829 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpBtZQPF/test.preprocessReads.minichunks.1367d91991002b/reports/shortReadReport_2 ...
2024-08-15 00:29:24.897494 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads_single_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:29:25.158173 INFO::preprocessReads.R/preprocessReads: starting...
2024-08-15 00:29:25.188658 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-08-15 00:29:25.191386 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:29:30.503088 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:29:30.506797 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpBtZQPF/test.preprocessReads_single_end.1367d961290bbc/chunks/chunk_000001/logs/progress.log
2024-08-15 00:29:33.457385 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.049 minutes
2024-08-15 00:29:33.58886 DEBUG::tools.R/processChunks: done
2024-08-15 00:29:33.592834 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-08-15 00:29:33.595602 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.preprocessReads_single_end.1367d961290bbc/results/test_se.adapter_contaminated_1.RData
2024-08-15 00:29:33.619834 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=26 highqual_reads=25 adapter_contam=1 read_length=75 rRNA_contam_reads=0 processed_reads=25 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-08-15 00:29:33.623142 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.preprocessReads_single_end.1367d961290bbc/results/test_se.summary_preprocess.tab
2024-08-15 00:29:33.643253 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpBtZQPF/test.preprocessReads_single_end.1367d961290bbc/bams/processed.aligner_input_1.fastq ...
2024-08-15 00:29:33.679554 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpBtZQPF/test.preprocessReads_single_end.1367d961290bbc/reports/shortReadReport_1 ...
2024-08-15 00:29:37.444431 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.readRNASeqEnds  ...  done successfully.



Executing test function test.readRNASeqEnds.dupmark  ...  done successfully.



Executing test function test.how_many  ...  done successfully.



Executing test function test.plotDF  ...  done successfully.



Executing test function test.relativeBarPlot  ...  done successfully.



Executing test function test.runPipeline  ... checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:29:39.637236 INFO::preprocessReads.R/preprocessReads: starting...
2024-08-15 00:29:39.699193 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_1.fastq.gz
2024-08-15 00:29:39.754819 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_2.fastq.gz
2024-08-15 00:29:39.759232 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:29:50.697285 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:29:50.699043 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-08-15 00:29:54.331877 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.061 minutes
2024-08-15 00:29:54.475732 DEBUG::tools.R/processChunks: done
2024-08-15 00:29:54.49826 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-08-15 00:29:54.504504 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_1.RData
2024-08-15 00:29:54.509413 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-08-15 00:29:54.513345 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_2.RData
2024-08-15 00:29:54.533328 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=2500 highqual_reads=2500 adapter_contam=0 read_length=100 rRNA_contam_reads=0 processed_reads=2500 input_min_read_length=100 input_max_read_length=100 processed_min_read_length=71 processed_max_read_length=100
2024-08-15 00:29:54.538195 INFO::io.R/saveWithID: saving file= test/results/test.summary_preprocess.tab
2024-08-15 00:29:54.543517 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_1.fastq ...
2024-08-15 00:29:54.55663 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_2.fastq ...
2024-08-15 00:29:54.569328 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_1 ...
2024-08-15 00:29:58.180382 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_2 ...
2024-08-15 00:30:01.938186 INFO::preprocessReads.R/preprocessReads: done
2024-08-15 00:30:02.159116 INFO::alignReads.R/alignReads: starting alignment...
2024-08-15 00:30:02.167237 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:30:07.778857 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:30:07.780962 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
[bam_translate] PG tag "A" on read "HISEQ1:109:D093LACXX:4:2205:16499:6611" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "HISEQ1:109:D093LACXX:4:1206:17367:135118" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "HISEQ1:109:D093LACXX:4:1304:1838:53573" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "HISEQ1:109:D093LACXX:4:2303:2956:116587" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "M" on read "HISEQ1:109:D093LACXX:4:2205:16499:6611" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "T" on read "HISEQ1:109:D093LACXX:4:1206:20028:108227" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "T" on read "HISEQ1:109:D093LACXX:4:1207:19518:143960" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "T" on read "HISEQ1:109:D093LACXX:4:2207:4065:173048" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-08-15 00:30:13.539534 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.096 minutes
2024-08-15 00:30:13.541911 DEBUG::tools.R/processChunks: done
2024-08-15 00:30:13.543428 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
2024-08-15 00:30:13.578518 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-08-15 00:30:13.586476 INFO::io.R/saveWithID: saving file= test/results/test.summary_alignment.tab
2024-08-15 00:30:13.592699 INFO::io.R/saveWithID: saving file= test/results/test.summary_analyzed_bamstats.tab
2024-08-15 00:30:13.595482 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-08-15 00:30:13.762156 INFO::io.R/saveWithID: saving file= test/results/test.summary_target_lengths.tab
2024-08-15 00:30:13.81184 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-08-15 00:30:13.812897 INFO::alignReads.R/alignReads: done
2024-08-15 00:30:13.951382 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-08-15 00:30:13.980913 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:30:18.548162 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:30:18.550296 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-08-15 00:30:21.074186 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.042 minutes
2024-08-15 00:30:21.07788 DEBUG::tools.R/processChunks: done
2024-08-15 00:30:21.080394 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-08-15 00:30:21.094979 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon.tab
2024-08-15 00:30:21.109963 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon_disjoint.tab
2024-08-15 00:30:21.121018 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene.tab
2024-08-15 00:30:21.126719 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_coding.tab
2024-08-15 00:30:21.13272 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_exonic.tab
2024-08-15 00:30:21.138586 INFO::io.R/saveWithID: saving file= test/results/test.counts_intergenic.tab
2024-08-15 00:30:21.147904 INFO::io.R/saveWithID: saving file= test/results/test.counts_intron.tab
2024-08-15 00:30:21.156028 INFO::countGenomicFeatures.R/mergeCounts: done
2024-08-15 00:30:21.161608 INFO::io.R/saveWithID: saving file= test/results/test.summary_counts.tab
2024-08-15 00:30:21.164225 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-08-15 00:30:21.406448 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-08-15 00:30:21.407619 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-08-15 00:30:21.560266 INFO::coverage.R/calculateCoverage: starting...
2024-08-15 00:30:21.565466 DEBUG::tools.R/processChunks: starting...
2024-08-15 00:30:25.264974 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-08-15 00:30:25.267422 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-08-15 00:30:27.859863 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.043 minutes
2024-08-15 00:30:27.8624 DEBUG::tools.R/processChunks: done
2024-08-15 00:30:29.184926 INFO::io.R/saveWithID: saving file= test/results/test.coverage.RData
2024-08-15 00:30:29.186466 INFO::coverage.R/saveCoverage: saving file= test/results/test.coverage.bw
2024-08-15 00:30:29.260326 INFO::io.R/saveWithID: saving file= test/results/test.summary_coverage.tab
2024-08-15 00:30:29.261636 INFO::coverage.R/calculateCoverage: done
2024-08-15 00:30:29.263037 INFO::analyzeVariants/analyzeVariants: starting ...
2024-08-15 00:30:29.36305 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-08-15 00:30:40.3304 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-08-15 00:30:40.40547 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-08-15 00:30:40.420331 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-08-15 00:30:40.421552 INFO::io.R/saveWithID: saving file= test/results/test.raw_variants.RData
2024-08-15 00:30:40.423806 INFO::io.R/saveWithID: saving file= test/results/test.filtered_variants.RData
2024-08-15 00:30:40.425026 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-08-15 00:30:40.42593 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-08-15 00:30:40.624446 INFO::analyzeVariants.R/writeVCF: ...done
2024-08-15 00:30:40.719496 INFO::io.R/saveWithID: saving file= test/results/test.summary_variants.tab
2024-08-15 00:30:40.721495 INFO::analyzeVariants/analyzeVariants: done
2024-08-15 00:30:40.728052 INFO::Pipeline run successful.
 done successfully.



Executing test function test.calculateTargetLength  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpBtZQPF/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-08-15 00:30:40.972112 INFO::io.R/saveWithID: saving file= /tmp/RtmpBtZQPF/test.calcTargetLengths.1367d9f6ff880/results/test_pe.summary_target_lengths.tab
 done successfully.



Executing test function test.sclapply  ...  done successfully.



Executing test function test.tryKeepTraceback  ...  done successfully.



Executing test function test.truncateReads  ...  done successfully.



Executing test function test.truncateReads.trim5  ...  done successfully.

RUNIT TEST PROTOCOL -- Thu Aug 15 00:30:54 2024 
*********************************************** 
Number of test functions: 61 
Number of deactivated test functions: 10 
Number of errors: 0 
Number of failures: 0 

 
1 Test Suite : 
HTSeqGenie unit testing - 61 test functions, 0 errors, 0 failures



Details 
*************************** 
Test Suite: HTSeqGenie unit testing 
Test function regexp: ^test.+ 
Test file regexp: ^runit.+\.[rR]$ 
Involved directory: 
/home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests 
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.alignReads.R 
test.alignReads: (2 checks) ... OK (26.75 seconds)
test.alignReads.sparsechunks: (2 checks) ... OK (16.55 seconds)
test.alignReadsOneSingleEnd: (2 checks) ... OK (0.48 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.analyzeVariants.R 
test.annotateVariants : DEACTIVATED, Skipped annotateVariants() test
test.callVariantsVariantTools.genotype: (2 checks) ... OK (67.84 seconds)
test.wrap.callVariants: (4 checks) ... OK (10.41 seconds)
test.wrap.callVariants.filters: (2 checks) ... OK (20.48 seconds)
test.wrap.callVariants.which: (1 checks) ... OK (4.42 seconds)
test.writeVCF.NULL: (1 checks) ... OK (0.13 seconds)
test.writeVCF.vcfStat: (4 checks) ... OK (0.47 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.bamUtils.R 
test.isFirstFragment: (5 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.buildGenomicFeatures.R 
test.buildCountsGRangesList: (3 checks) ... OK (27.34 seconds)
test.generateSingleGeneDERs: (4 checks) ... OK (24.9 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.calculateCoverage.R 
test.computeCoverage: (9 checks) ... OK (0.68 seconds)
test.isSparse: (5 checks) ... OK (0.1 seconds)
test.mergeCoverage: (1 checks) ... OK (1.48 seconds)
test.mergeCoverage.sparse: (2 checks) ... OK (1.15 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.checkConfig.R 
test.checkConfig.analyzeVariants: (5 checks) ... OK (0.13 seconds)
test.findTemplate: (5 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.config.R 
test.checkConfig: (5 checks) ... OK (0.3 seconds)
test.checkConfig.alignReads: (5 checks) ... OK (0.34 seconds)
test.getConfig: (14 checks) ... OK (0 seconds)
test.loadConfig: (2 checks) ... OK (0 seconds)
test.parseDCF: (7 checks) ... OK (0 seconds)
test.updateConfig: (1 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.detectAdapterContam.R 
test.getAdapterSeqs: (5 checks) ... OK (0.03 seconds)
test.isAdapter: (5 checks) ... OK (0.11 seconds)
test.isAdapter3.primeEnd: (1 checks) ... OK (0.07 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.detectRRNA.R 
test.detectRRNA: (1 checks) ... OK (0.27 seconds)
test.detectRRNA.paired_end: (1 checks) ... OK (0.36 seconds)
test.getRRNAIds: (1 checks) ... OK (0.23 seconds)
test.getRRNAIds_random: (1 checks) ... OK (0.2 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.filterQuality.R 
test.filterByLength: (2 checks) ... OK (0.06 seconds)
test.isAboveQualityThresh: (3 checks) ... OK (0.04 seconds)
test.trimTailsByQuality: (4 checks) ... OK (0.03 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.gatk.R 
test.callVariantsGATK : DEACTIVATED, callVariantsGATK() tests need gatk.path option set
test.callVariantsGATK.withFiltering : DEACTIVATED, callVariantsGATK() tests need gatk.path option set
test.checkGATKJar : DEACTIVATED, checkGATKJar() test needs gatk.path option set
test.excludeVariantsByRegion: (3 checks) ... OK (0.14 seconds)
test.gatk : DEACTIVATED, gatk() tests need gatk.path option set
test.realignIndels : DEACTIVATED, test.realignIndels() tests need gatk.path option set
test.realignIndelsGATK : DEACTIVATED, realignIndelsGATK() tests need gatk.path option set
test.realignIndelsGATK.parallel : DEACTIVATED, realignIndelsGATK() tests need gatk.path option set
test_zipUp: (3 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.io.R 
test.FastQStreamer.getReads.pefq: (1 checks) ... OK (0.18 seconds)
test.FastQStreamer.getReads.pefq.subsample: (1 checks) ... OK (0.31 seconds)
test.FastQStreamer.getReads.segz: (1 checks) ... OK (0.14 seconds)
test.FastQStreamer.getReads.truncated: (1 checks) ... OK (0.17 seconds)
test.FastQStreamer.subsampler.isdeterministic: (3 checks) ... OK (1.61 seconds)
test.createTmpDir: (4 checks) ... OK (0 seconds)
test.detectQualityInFASTQFile: (3 checks) ... OK (0.1 seconds)
test.getObjectFilename: (4 checks) ... OK (0 seconds)
test.safeUnlink: (2 checks) ... OK (0.01 seconds)
test.writeAudit: (0 checks) ... OK (0.16 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.mergeLanes.R 
test.mergeLanes: (6 checks) ... OK (58.19 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.picard.R 
test.markDuplicates : DEACTIVATED, Skipped markDuplicates() test
test.markDuplicates_w_outfile : DEACTIVATED, Skipped markDuplicates() test
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.preprocessReads.R 
test.preprocessReads: (5 checks) ... OK (9.35 seconds)
test.preprocessReads.minichunks: (5 checks) ... OK (13.76 seconds)
test.preprocessReads_single_end: (5 checks) ... OK (12.55 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.readRNASeqEnds.R 
test.readRNASeqEnds: (6 checks) ... OK (0.37 seconds)
test.readRNASeqEnds.dupmark: (2 checks) ... OK (0.38 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.reportPipelineQA.R 
test.how_many: (3 checks) ... OK (0 seconds)
test.plotDF: (3 checks) ... OK (0.42 seconds)
test.relativeBarPlot: (2 checks) ... OK (0.17 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.runPipeline.R 
test.runPipeline: (1 checks) ... OK (61.91 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.targetLengths.R 
test.calculateTargetLength: (4 checks) ... OK (0.24 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.tools.R 
test.sclapply: (10 checks) ... OK (13.44 seconds)
test.tryKeepTraceback: (3 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.trimReads.R 
test.truncateReads: (7 checks) ... OK (0.05 seconds)
test.truncateReads.trim5: (15 checks) ... OK (0.15 seconds) 

runTests.R: OK !
There were 50 or more warnings (use warnings() to see the first 50)
> 
> proc.time()
   user  system elapsed 
253.375  86.354 395.576

Example timings

HTSeqGenie.Rcheck/HTSeqGenie-Ex.timings

name	user	system	elapsed
HTSeqGenie	0	0	0
buildGenomicFeaturesFromTxDb	0	0	0
runPipeline	0	0	0