Multiple platform build/check report for BioC 3.19 - CHECK results for HTSeqGenie on nebbiolo1

Hostname	OS	Arch (*)	R version	Installed pkgs
nebbiolo1	Linux (Ubuntu 22.04.3 LTS)	x86_64	4.4.0 (2024-04-24) -- "Puppy Cup"	4758
palomino3	Windows Server 2022 Datacenter	x64	4.4.0 (2024-04-24 ucrt) -- "Puppy Cup"	4492
merida1	macOS 12.7.4 Monterey	x86_64	4.4.0 (2024-04-24) -- "Puppy Cup"	4464
kjohnson1	macOS 13.6.6 Ventura	arm64	4.4.0 (2024-04-24) -- "Puppy Cup"	4464
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 nebbiolo1

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.34.0

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

StartedAt: 2024-06-17 00:09:14 -0400 (Mon, 17 Jun 2024)

EndedAt: 2024-06-17 00:22:51 -0400 (Mon, 17 Jun 2024)

EllapsedTime: 816.8 seconds

RetCode: 0

Status: OK

CheckDir: HTSeqGenie.Rcheck

Warnings: 0

Command output

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


* using log directory ‘/home/biocbuild/bbs-3.19-bioc/meat/HTSeqGenie.Rcheck’
* using R version 4.4.0 (2024-04-24)
* 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.34.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.19-bioc/meat/HTSeqGenie.Rcheck/00check.log’
for details.

Installation output

HTSeqGenie.Rcheck/00install.out

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


* installing to library ‘/home/biocbuild/bbs-3.19-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.0 (2024-04-24) -- "Puppy Cup"
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/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:14:59.595398 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-17 00:14:59.603787 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:14:59.60708 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-17 00:14:59.608964 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:15:02.326698 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:15:02.328134 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/chunks/chunk_000001/logs/progress.log
2024-06-17 00:15:05.059525 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.046 minutes
2024-06-17 00:15:05.0609 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/chunks/chunk_000002/logs/progress.log
2024-06-17 00:15:07.789461 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.045 minutes
2024-06-17 00:15:07.791289 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/chunks/chunk_000003/logs/progress.log
2024-06-17 00:15:10.503848 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.045 minutes
2024-06-17 00:15:10.534401 DEBUG::tools.R/processChunks: done
2024-06-17 00:15:10.538346 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-17 00:15:10.540654 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/results/test_pe.adapter_contaminated_1.RData
2024-06-17 00:15:10.543392 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-17 00:15:10.544971 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/results/test_pe.adapter_contaminated_2.RData
2024-06-17 00:15:10.55408 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-06-17 00:15:10.556361 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/results/test_pe.summary_preprocess.tab
2024-06-17 00:15:10.559647 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/bams/processed.aligner_input_1.fastq ...
2024-06-17 00:15:10.563523 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/bams/processed.aligner_input_2.fastq ...
2024-06-17 00:15:10.566452 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/reports/shortReadReport_1 ...
2024-06-17 00:15:11.893166 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/reports/shortReadReport_2 ...
2024-06-17 00:15:12.965582 INFO::preprocessReads.R/preprocessReads: done
2024-06-17 00:15:13.028974 INFO::alignReads.R/alignReads: starting alignment...
2024-06-17 00:15:13.034677 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:15:15.596214 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:15:15.598037 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/chunks/chunk_000001/logs/progress.log
2024-06-17 00:15:18.457288 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.048 minutes
2024-06-17 00:15:18.458814 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/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.
2024-06-17 00:15:21.075407 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.044 minutes
2024-06-17 00:15:21.077058 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/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-06-17 00:15:23.721969 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.044 minutes
2024-06-17 00:15:23.725057 DEBUG::tools.R/processChunks: done
2024-06-17 00:15:23.726685 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 "T" 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 "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-06-17 00:15:23.953823 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-06-17 00:15:23.963918 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/results/test_pe.summary_alignment.tab
2024-06-17 00:15:23.971635 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/results/test_pe.summary_analyzed_bamstats.tab
2024-06-17 00:15:23.973402 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-06-17 00:15:24.22156 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.alignReads.284c913c1beea0/results/test_pe.summary_target_lengths.tab
2024-06-17 00:15:24.268168 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-06-17 00:15:24.269274 INFO::alignReads.R/alignReads: done
 done successfully.



Executing test function test.alignReads.sparsechunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:15:24.526947 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-17 00:15:24.530491 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:15:24.592741 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 2 , totnbreads= 26 )
2024-06-17 00:15:24.597425 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:15:24.600382 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-17 00:15:24.602367 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:15:27.377785 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:15:27.379223 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmpl0EpYe/test.alignReads.sparsechunks.284c913cfe2846/chunks/chunk_000001/logs/progress.log
2024-06-17 00:15:30.096019 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.045 minutes
2024-06-17 00:15:30.097495 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmpl0EpYe/test.alignReads.sparsechunks.284c913cfe2846/chunks/chunk_000002/logs/progress.log
2024-06-17 00:15:32.788438 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.045 minutes
2024-06-17 00:15:32.789855 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmpl0EpYe/test.alignReads.sparsechunks.284c913cfe2846/chunks/chunk_000003/logs/progress.log
2024-06-17 00:15:35.520832 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.045 minutes
2024-06-17 00:15:35.522114 DEBUG::tools.R/processChunks: starting chunkid= 4 ; see logfile= /tmp/Rtmpl0EpYe/test.alignReads.sparsechunks.284c913cfe2846/chunks/chunk_000004/logs/progress.log
2024-06-17 00:15:38.236031 DEBUG::tools.R/processChunks: done with chunkid= 4 ; elapsed.time= 0.045 minutes
2024-06-17 00:15:38.268896 DEBUG::tools.R/processChunks: done
2024-06-17 00:15:38.272444 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-17 00:15:38.274787 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.alignReads.sparsechunks.284c913cfe2846/results/test_pe.adapter_contaminated_1.RData
2024-06-17 00:15:38.277671 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-17 00:15:38.279342 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.alignReads.sparsechunks.284c913cfe2846/results/test_pe.adapter_contaminated_2.RData
2024-06-17 00:15:38.2896 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-06-17 00:15:38.291907 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.alignReads.sparsechunks.284c913cfe2846/results/test_pe.summary_preprocess.tab
2024-06-17 00:15:38.295515 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmpl0EpYe/test.alignReads.sparsechunks.284c913cfe2846/bams/processed.aligner_input_1.fastq ...
2024-06-17 00:15:38.300586 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmpl0EpYe/test.alignReads.sparsechunks.284c913cfe2846/bams/processed.aligner_input_2.fastq ...
2024-06-17 00:15:38.303753 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmpl0EpYe/test.alignReads.sparsechunks.284c913cfe2846/reports/shortReadReport_1 ...
2024-06-17 00:15:39.545706 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmpl0EpYe/test.alignReads.sparsechunks.284c913cfe2846/reports/shortReadReport_2 ...
2024-06-17 00:15:40.514252 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.alignReadsOneSingleEnd  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:15:40.698626 INFO::alignReads.R/alignReadsChunk: running gsnap...
2024-06-17 00:15:40.702821 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/Rtmpl0EpYe/test.alignReadsOneSingleEnd.284c91668d5f25/bams/test.alignReads /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq 2>&1
2024-06-17 00:15:40.916316 INFO::alignReads.R/createSummaryAlignment: counting unique bam reads...
2024-06-17 00:15:41.007614 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.alignReadsOneSingleEnd.284c91668d5f25/results/test.alignReads.summary_alignment.tab
2024-06-17 00:15:41.049527 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.alignReadsOneSingleEnd.284c91668d5f25/results/test.alignReads.summary_analyzed_bamstats.tab
2024-06-17 00:15:41.051229 INFO::alignReads.R/alignReadsChunk: done
 done successfully.



Executing test function test.annotateVariants  ... Timing stopped at: 0.002 0 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/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:15:41.336504 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.genotype.284c917091390b/results/test_pe.coverage.RData
2024-06-17 00:15:41.338424 INFO::coverage.R/saveCoverage: saving file= /tmp/Rtmpl0EpYe/test.genotype.284c917091390b/results/test_pe.coverage.bw
2024-06-17 00:15:41.445844 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.genotype.284c917091390b/results/test_pe.summary_coverage.tab
2024-06-17 00:15:41.447526 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-17 00:15:51.270752 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-17 00:15:51.344458 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-17 00:15:51.358906 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-17 00:15:51.360294 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.genotype.284c917091390b/results/test_pe.raw_variants.RData
2024-06-17 00:15:51.362526 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.genotype.284c917091390b/results/test_pe.filtered_variants.RData
2024-06-17 00:15:51.363754 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-17 00:15:51.364817 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-17 00:15:51.715557 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-17 00:15:51.716724 INFO::analyzeVariants.R/.callGenotypes: calling genotypes...
2024-06-17 00:16:45.89715 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-17 00:16:46.285529 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-17 00:16:46.286396 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/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:16:46.688084 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-17 00:16:56.372857 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-17 00:16:56.445052 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-17 00:16:56.460178 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-17 00:16:56.461488 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.wrap.callVariants.284c91e7afa5b/results/test_pe.raw_variants.RData
2024-06-17 00:16:56.463777 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.wrap.callVariants.284c91e7afa5b/results/test_pe.filtered_variants.RData
2024-06-17 00:16:56.465026 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.filters  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:16:56.601797 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-17 00:17:06.591332 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-17 00:17:06.648535 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-17 00:17:06.665424 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-17 00:17:06.666805 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.wrap.callVariants.filters.284c9137478e48/results/test_pe.raw_variants.RData
2024-06-17 00:17:06.669161 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.wrap.callVariants.filters.284c9137478e48/results/test_pe.filtered_variants.RData
2024-06-17 00:17:06.670414 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-17 00:17:06.671901 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-17 00:17:16.572709 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-17 00:17:16.610631 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-17 00:17:16.627172 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-17 00:17:16.628585 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.wrap.callVariants.filters.284c9137478e48/results/test_pe.raw_variants.RData
2024-06-17 00:17:16.631338 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.wrap.callVariants.filters.284c9137478e48/results/test_pe.filtered_variants.RData
2024-06-17 00:17:16.633445 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.which  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:17:16.871268 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-17 00:17:16.872675 INFO::analyzeVariants.R/buildTallyParam: restricting variant calls using 'which'
2024-06-17 00:17:19.340698 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-17 00:17:19.406605 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-17 00:17:19.421236 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-17 00:17:19.422482 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.wrap.callVariants.which.284c911468b1d8/results/test_pe.raw_variants.RData
2024-06-17 00:17:19.423987 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.wrap.callVariants.which.284c911468b1d8/results/test_pe.filtered_variants.RData
2024-06-17 00:17:19.425147 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.writeVCF.NULL  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:17:19.570896 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-17 00:17:19.572055 INFO::analyzeVariants.R/writeVCF: ...done
 done successfully.



Executing test function test.writeVCF.vcfStat  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:17:21.048873 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-17 00:17:21.236208 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-06-17 00:18:12.374632 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/mgefhdpl/merged/results/bla.coverage.RData
2024-06-17 00:18:12.377325 INFO::coverage.R/saveCoverage: saving file= /tmp/Rtmpl0EpYe/mgefhdpl/merged/results/bla.coverage.bw
2024-06-17 00:18:12.45868 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/mgefhdpl/merged/results/bla.summary_coverage.tab
 done successfully.



Executing test function test.mergeCoverage.sparse  ... 2024-06-17 00:18:13.586829 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/zfselrxq/merged/results/bla.coverage.RData
2024-06-17 00:18:13.588371 INFO::coverage.R/saveCoverage: saving file= /tmp/Rtmpl0EpYe/zfselrxq/merged/results/bla.coverage.bw
2024-06-17 00:18:13.599004 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/zfselrxq/merged/results/bla.summary_coverage.tab
 done successfully.



Executing test function test.checkConfig.analyzeVariants  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-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/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-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/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-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/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:18:14.828728 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-06-17 00:18:14.829866 INFO::io.R/writeFastQFiles: writing filename= /tmp/Rtmpl0EpYe/test.detectRRNA.284c9141eef52c/bams/rRNA_contam/input1.fastq
2024-06-17 00:18:14.832973 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/Rtmpl0EpYe/test.detectRRNA.284c9141eef52c/bams/rRNA_contam/test_se /tmp/Rtmpl0EpYe/test.detectRRNA.284c9141eef52c/bams/rRNA_contam/input1.fastq 2>&1
2024-06-17 00:18:15.094157 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-06-17 00:18:15.095198 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.detectRRNA.paired_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:18:15.25302 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-06-17 00:18:15.254011 INFO::io.R/writeFastQFiles: writing filename= /tmp/Rtmpl0EpYe/test.detectRRNA.paired_end.284c917c671589/bams/rRNA_contam/input1.fastq
2024-06-17 00:18:15.255575 INFO::io.R/writeFastQFiles: writing filename= /tmp/Rtmpl0EpYe/test.detectRRNA.paired_end.284c917c671589/bams/rRNA_contam/input2.fastq
2024-06-17 00:18:15.257665 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/Rtmpl0EpYe/test.detectRRNA.paired_end.284c917c671589/bams/rRNA_contam/test_pe /tmp/Rtmpl0EpYe/test.detectRRNA.paired_end.284c917c671589/bams/rRNA_contam/input1.fastq -a paired /tmp/Rtmpl0EpYe/test.detectRRNA.paired_end.284c917c671589/bams/rRNA_contam/input2.fastq 2>&1
2024-06-17 00:18:15.544256 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-06-17 00:18:15.545314 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.getRRNAIds  ... 2024-06-17 00:18:15.56538 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/Rtmpl0EpYe/test_get_rRNA_idsjdxfqgwh/test_pe /tmp/Rtmpl0EpYe/test_get_rRNA_idsjdxfqgwh/1.fastq -a paired /tmp/Rtmpl0EpYe/test_get_rRNA_idsjdxfqgwh/2.fastq 2>&1
 done successfully.



Executing test function test.getRRNAIds_random  ... 2024-06-17 00:18:15.868478 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/Rtmpl0EpYe/test_get_rRNAIds_randomwfqtgilh/test_pe /tmp/Rtmpl0EpYe/test_get_rRNAIds_randomwfqtgilh/1.fastq 2>&1
 done successfully.



Executing test function test.filterByLength  ... 2024-06-17 00:18:16.091506 INFO::filterQuality.R/filterQuality: filterByLength...
2024-06-17 00:18:16.093012 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 0.5
2024-06-17 00:18:16.093908 INFO::filterQuality.R/filterByLength: done
2024-06-17 00:18:16.141676 INFO::filterQuality.R/filterQuality: filterByLength...
2024-06-17 00:18:16.142834 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 1
2024-06-17 00:18:16.143784 INFO::filterQuality.R/filterByLength: done
 done successfully.



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



Executing test function test.trimTailsByQuality  ... 2024-06-17 00:18:16.198156 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-06-17 00:18:16.2078 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-06-17 00:18:16.209004 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-06-17 00:18:16.213793 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-06-17 00:18:16.214865 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-06-17 00:18:16.219558 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-06-17 00:18:16.220597 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-06-17 00:18:16.225372 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.001
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 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.001
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/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:18:16.516694 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:18:16.518923 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-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/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:18:16.69232 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:18:16.791684 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-06-17 00:18:16.794394 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:18:16.796493 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-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/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:18:17.016307 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-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/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:18:17.156338 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-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/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:18:17.349935 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:18:17.417121 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-06-17 00:18:17.419591 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:18:17.42176 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:18:17.623493 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:18:17.664608 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-06-17 00:18:17.667074 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:18:17.669143 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-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/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
 done successfully.



Executing test function test.mergeLanes  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:18:18.389064 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-17 00:18:18.395603 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:18:18.399645 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-17 00:18:18.402345 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:18:21.700191 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:18:21.701609 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/chunks/chunk_000001/logs/progress.log
2024-06-17 00:18:24.275414 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.043 minutes
2024-06-17 00:18:24.276735 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/chunks/chunk_000002/logs/progress.log
2024-06-17 00:18:26.82708 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.042 minutes
2024-06-17 00:18:26.828529 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/chunks/chunk_000003/logs/progress.log
2024-06-17 00:18:29.407353 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-06-17 00:18:29.443581 DEBUG::tools.R/processChunks: done
2024-06-17 00:18:29.446308 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-17 00:18:29.447943 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.adapter_contaminated_1.RData
2024-06-17 00:18:29.450043 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-17 00:18:29.451608 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.adapter_contaminated_2.RData
2024-06-17 00:18:29.459517 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-06-17 00:18:29.461186 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.summary_preprocess.tab
2024-06-17 00:18:29.463416 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/bams/processed.aligner_input_1.fastq ...
2024-06-17 00:18:29.46722 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/bams/processed.aligner_input_2.fastq ...
2024-06-17 00:18:29.470294 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/reports/shortReadReport_1 ...
2024-06-17 00:18:30.736521 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/reports/shortReadReport_2 ...
2024-06-17 00:18:31.722353 INFO::preprocessReads.R/preprocessReads: done
2024-06-17 00:18:31.813115 INFO::alignReads.R/alignReads: starting alignment...
2024-06-17 00:18:31.817829 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:18:34.790901 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:18:34.792578 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/chunks/chunk_000001/logs/progress.log
2024-06-17 00:18:37.320545 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.042 minutes
2024-06-17 00:18:37.321944 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/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.
2024-06-17 00:18:39.854188 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.042 minutes
2024-06-17 00:18:39.855842 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/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-06-17 00:18:42.408273 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-06-17 00:18:42.410542 DEBUG::tools.R/processChunks: done
2024-06-17 00:18:42.412174 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 "T" 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 "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-06-17 00:18:42.591447 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-06-17 00:18:42.598867 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.summary_alignment.tab
2024-06-17 00:18:42.605204 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.summary_analyzed_bamstats.tab
2024-06-17 00:18:42.606997 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-06-17 00:18:42.827869 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.summary_target_lengths.tab
2024-06-17 00:18:42.873264 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-06-17 00:18:42.874263 INFO::alignReads.R/alignReads: done
2024-06-17 00:18:42.968405 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-06-17 00:18:42.987033 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:18:45.905663 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:18:45.907372 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/chunks/chunk_000001/logs/progress.log
2024-06-17 00:18:48.333851 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.04 minutes
2024-06-17 00:18:48.335903 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/chunks/chunk_000002/logs/progress.log
2024-06-17 00:18:50.772249 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.041 minutes
2024-06-17 00:18:50.773972 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/chunks/chunk_000003/logs/progress.log
2024-06-17 00:18:53.215865 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.041 minutes
2024-06-17 00:18:53.219053 DEBUG::tools.R/processChunks: done
2024-06-17 00:18:53.221236 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-06-17 00:18:53.239145 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.counts_exon.tab
2024-06-17 00:18:53.255099 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.counts_exon_disjoint.tab
2024-06-17 00:18:53.264645 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.counts_gene.tab
2024-06-17 00:18:53.270807 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.counts_gene_coding.tab
2024-06-17 00:18:53.276172 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.counts_gene_exonic.tab
2024-06-17 00:18:53.281257 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.counts_intergenic.tab
2024-06-17 00:18:53.289972 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.counts_intron.tab
2024-06-17 00:18:53.293193 INFO::countGenomicFeatures.R/mergeCounts: done
2024-06-17 00:18:53.298101 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.summary_counts.tab
2024-06-17 00:18:53.299634 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-06-17 00:18:53.574798 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-06-17 00:18:53.575664 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-06-17 00:18:53.643785 INFO::coverage.R/calculateCoverage: starting...
2024-06-17 00:18:53.64807 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:18:56.399993 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:18:56.401713 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/chunks/chunk_000001/logs/progress.log
2024-06-17 00:18:58.579003 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.036 minutes
2024-06-17 00:18:58.581434 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/chunks/chunk_000002/logs/progress.log
2024-06-17 00:19:00.790822 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.037 minutes
2024-06-17 00:19:00.792552 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/chunks/chunk_000003/logs/progress.log
2024-06-17 00:19:02.96853 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.036 minutes
2024-06-17 00:19:02.970771 DEBUG::tools.R/processChunks: done
2024-06-17 00:19:04.264396 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.coverage.RData
2024-06-17 00:19:04.26583 INFO::coverage.R/saveCoverage: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.coverage.bw
2024-06-17 00:19:04.276932 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.summary_coverage.tab
2024-06-17 00:19:04.2782 INFO::coverage.R/calculateCoverage: done
2024-06-17 00:19:04.280593 INFO::analyzeVariants/analyzeVariants: starting ...
2024-06-17 00:19:04.369055 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-17 00:19:07.127798 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-17 00:19:07.194709 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-17 00:19:07.210491 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-17 00:19:07.211819 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.raw_variants.RData
2024-06-17 00:19:07.21329 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.filtered_variants.RData
2024-06-17 00:19:07.214443 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-17 00:19:07.215368 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-17 00:19:07.41113 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-17 00:19:07.500084 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/results/test_pe.summary_variants.tab
2024-06-17 00:19:07.501963 INFO::analyzeVariants/analyzeVariants: done
2024-06-17 00:19:07.505222 INFO::Pipeline run successful.
2024-06-17 00:19:07.653774 INFO::mergeLanes.R/doMergeLanes: starting...
2024-06-17 00:19:07.659182 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-17 00:19:07.66156 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.adapter_contaminated_1.RData
2024-06-17 00:19:07.664509 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-17 00:19:07.666488 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.adapter_contaminated_2.RData
2024-06-17 00:19:07.679105 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-06-17 00:19:07.681547 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.summary_preprocess.tab
2024-06-17 00:19:07.68393 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 "T" 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 "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-06-17 00:19:07.936577 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-06-17 00:19:07.945007 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.summary_alignment.tab
2024-06-17 00:19:07.955879 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.summary_analyzed_bamstats.tab
2024-06-17 00:19:07.958932 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-06-17 00:19:08.239143 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.summary_target_lengths.tab
2024-06-17 00:19:08.292917 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-06-17 00:19:08.338634 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-06-17 00:19:08.36115 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.counts_exon.tab
2024-06-17 00:19:08.374487 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.counts_exon_disjoint.tab
2024-06-17 00:19:08.382024 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.counts_gene.tab
2024-06-17 00:19:08.387693 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.counts_gene_coding.tab
2024-06-17 00:19:08.393087 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.counts_gene_exonic.tab
2024-06-17 00:19:08.398899 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.counts_intergenic.tab
2024-06-17 00:19:08.411256 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.counts_intron.tab
2024-06-17 00:19:08.414833 INFO::countGenomicFeatures.R/mergeCounts: done
2024-06-17 00:19:08.421256 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.summary_counts.tab
2024-06-17 00:19:08.423192 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-06-17 00:19:08.644247 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-06-17 00:19:10.530596 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.coverage.RData
2024-06-17 00:19:10.533246 INFO::coverage.R/saveCoverage: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.coverage.bw
2024-06-17 00:19:10.544515 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.summary_coverage.tab
2024-06-17 00:19:10.576578 INFO::analyzeVariants/analyzeVariants: starting ...
2024-06-17 00:19:10.658881 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-17 00:19:13.520486 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-17 00:19:13.587743 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-17 00:19:13.602857 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-17 00:19:13.604126 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.raw_variants.RData
2024-06-17 00:19:13.605766 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.filtered_variants.RData
2024-06-17 00:19:13.607111 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-17 00:19:13.608253 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-17 00:19:13.808066 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-17 00:19:13.900334 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.mergeLanes.284c9125639e97/merged/results/merged.summary_variants.tab
2024-06-17 00:19:13.902444 INFO::analyzeVariants/analyzeVariants: done
2024-06-17 00:19:13.906449 INFO::mergeLanes.R/doMergeLanes: merge lanes successful.
 done successfully.



Executing test function test.markDuplicates  ... Timing stopped at: 0 0 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.001 0 0.001
Error in DEACTIVATED("Skipped markDuplicates() test") : 
  Skipped markDuplicates() test
 done successfully.



Executing test function test.preprocessReads  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:19:14.191358 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-17 00:19:14.211989 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:19:14.229624 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-17 00:19:14.232277 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:19:17.231695 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:19:17.2333 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmpl0EpYe/test.preprocessReads.284c914874a9e6/chunks/chunk_000001/logs/progress.log
2024-06-17 00:19:19.797766 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.043 minutes
2024-06-17 00:19:19.834123 DEBUG::tools.R/processChunks: done
2024-06-17 00:19:19.836353 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-17 00:19:19.837815 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.preprocessReads.284c914874a9e6/results/test_pe.adapter_contaminated_1.RData
2024-06-17 00:19:19.839409 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-17 00:19:19.840795 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.preprocessReads.284c914874a9e6/results/test_pe.adapter_contaminated_2.RData
2024-06-17 00:19:19.846823 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-06-17 00:19:19.848512 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.preprocessReads.284c914874a9e6/results/test_pe.summary_preprocess.tab
2024-06-17 00:19:19.850294 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmpl0EpYe/test.preprocessReads.284c914874a9e6/bams/processed.aligner_input_1.fastq ...
2024-06-17 00:19:19.853589 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmpl0EpYe/test.preprocessReads.284c914874a9e6/bams/processed.aligner_input_2.fastq ...
2024-06-17 00:19:19.856574 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmpl0EpYe/test.preprocessReads.284c914874a9e6/reports/shortReadReport_1 ...
2024-06-17 00:19:21.148817 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmpl0EpYe/test.preprocessReads.284c914874a9e6/reports/shortReadReport_2 ...
2024-06-17 00:19:22.217037 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads.minichunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:19:22.479967 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-17 00:19:22.485777 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:19:22.489452 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-17 00:19:22.491788 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:19:25.509026 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:19:25.511052 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmpl0EpYe/test.preprocessReads.minichunks.284c91c0a87f1/chunks/chunk_000001/logs/progress.log
2024-06-17 00:19:28.158934 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-06-17 00:19:28.160358 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmpl0EpYe/test.preprocessReads.minichunks.284c91c0a87f1/chunks/chunk_000002/logs/progress.log
2024-06-17 00:19:30.751881 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.043 minutes
2024-06-17 00:19:30.753477 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmpl0EpYe/test.preprocessReads.minichunks.284c91c0a87f1/chunks/chunk_000003/logs/progress.log
2024-06-17 00:19:33.342983 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-06-17 00:19:33.384882 DEBUG::tools.R/processChunks: done
2024-06-17 00:19:33.387902 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-17 00:19:33.389705 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.preprocessReads.minichunks.284c91c0a87f1/results/test_pe.adapter_contaminated_1.RData
2024-06-17 00:19:33.391984 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-17 00:19:33.393612 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.preprocessReads.minichunks.284c91c0a87f1/results/test_pe.adapter_contaminated_2.RData
2024-06-17 00:19:33.403921 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-06-17 00:19:33.405936 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.preprocessReads.minichunks.284c91c0a87f1/results/test_pe.summary_preprocess.tab
2024-06-17 00:19:33.408484 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmpl0EpYe/test.preprocessReads.minichunks.284c91c0a87f1/bams/processed.aligner_input_1.fastq ...
2024-06-17 00:19:33.414396 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmpl0EpYe/test.preprocessReads.minichunks.284c91c0a87f1/bams/processed.aligner_input_2.fastq ...
2024-06-17 00:19:33.418995 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmpl0EpYe/test.preprocessReads.minichunks.284c91c0a87f1/reports/shortReadReport_1 ...
2024-06-17 00:19:34.717576 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmpl0EpYe/test.preprocessReads.minichunks.284c91c0a87f1/reports/shortReadReport_2 ...
2024-06-17 00:19:35.706508 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads_single_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:19:35.941099 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-17 00:19:35.961002 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-17 00:19:35.963472 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:19:38.721775 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:19:38.723789 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmpl0EpYe/test.preprocessReads_single_end.284c9139d5f3bf/chunks/chunk_000001/logs/progress.log
2024-06-17 00:19:41.084579 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.039 minutes
2024-06-17 00:19:41.094769 DEBUG::tools.R/processChunks: done
2024-06-17 00:19:41.098421 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-17 00:19:41.100554 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.preprocessReads_single_end.284c9139d5f3bf/results/test_se.adapter_contaminated_1.RData
2024-06-17 00:19:41.1076 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-06-17 00:19:41.109427 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.preprocessReads_single_end.284c9139d5f3bf/results/test_se.summary_preprocess.tab
2024-06-17 00:19:41.11143 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmpl0EpYe/test.preprocessReads_single_end.284c9139d5f3bf/bams/processed.aligner_input_1.fastq ...
2024-06-17 00:19:41.11533 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmpl0EpYe/test.preprocessReads_single_end.284c9139d5f3bf/reports/shortReadReport_1 ...
2024-06-17 00:19:42.382726 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.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:19:42.993099 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-17 00:19:43.014413 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_1.fastq.gz
2024-06-17 00:19:43.03535 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_2.fastq.gz
2024-06-17 00:19:43.037965 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:19:45.945486 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:19:45.946939 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-06-17 00:19:49.168207 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.054 minutes
2024-06-17 00:19:49.316796 DEBUG::tools.R/processChunks: done
2024-06-17 00:19:49.320779 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-17 00:19:49.323266 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_1.RData
2024-06-17 00:19:49.326511 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-17 00:19:49.329077 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_2.RData
2024-06-17 00:19:49.356667 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-06-17 00:19:49.443533 INFO::io.R/saveWithID: saving file= test/results/test.summary_preprocess.tab
2024-06-17 00:19:49.44752 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_1.fastq ...
2024-06-17 00:19:49.474825 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_2.fastq ...
2024-06-17 00:19:49.502586 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_1 ...
2024-06-17 00:19:53.714784 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_2 ...
2024-06-17 00:19:56.369514 INFO::preprocessReads.R/preprocessReads: done
2024-06-17 00:19:56.70648 INFO::alignReads.R/alignReads: starting alignment...
2024-06-17 00:19:56.713972 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:20:05.401252 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:20:05.405567 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-06-17 00:20:10.751225 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.089 minutes
2024-06-17 00:20:10.754698 DEBUG::tools.R/processChunks: done
2024-06-17 00:20:10.756751 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
2024-06-17 00:20:10.805367 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-06-17 00:20:10.814424 INFO::io.R/saveWithID: saving file= test/results/test.summary_alignment.tab
2024-06-17 00:20:10.822225 INFO::io.R/saveWithID: saving file= test/results/test.summary_analyzed_bamstats.tab
2024-06-17 00:20:10.825267 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-06-17 00:20:11.014357 INFO::io.R/saveWithID: saving file= test/results/test.summary_target_lengths.tab
2024-06-17 00:20:11.062609 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-06-17 00:20:11.063791 INFO::alignReads.R/alignReads: done
2024-06-17 00:20:11.179692 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-06-17 00:20:11.204903 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:20:15.11123 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:20:15.114145 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-06-17 00:20:18.040127 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.049 minutes
2024-06-17 00:20:18.045327 DEBUG::tools.R/processChunks: done
2024-06-17 00:20:18.048709 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-06-17 00:20:18.068941 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon.tab
2024-06-17 00:20:18.086275 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon_disjoint.tab
2024-06-17 00:20:18.099491 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene.tab
2024-06-17 00:20:18.108777 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_coding.tab
2024-06-17 00:20:18.117372 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_exonic.tab
2024-06-17 00:20:18.125599 INFO::io.R/saveWithID: saving file= test/results/test.counts_intergenic.tab
2024-06-17 00:20:18.138835 INFO::io.R/saveWithID: saving file= test/results/test.counts_intron.tab
2024-06-17 00:20:18.146575 INFO::countGenomicFeatures.R/mergeCounts: done
2024-06-17 00:20:18.153906 INFO::io.R/saveWithID: saving file= test/results/test.summary_counts.tab
2024-06-17 00:20:18.157756 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-06-17 00:20:18.546502 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-06-17 00:20:18.548054 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-06-17 00:20:18.703224 INFO::coverage.R/calculateCoverage: starting...
2024-06-17 00:20:18.711369 DEBUG::tools.R/processChunks: starting...
2024-06-17 00:20:24.436939 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-17 00:20:24.438937 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-06-17 00:20:27.044084 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.043 minutes
2024-06-17 00:20:27.048568 DEBUG::tools.R/processChunks: done
2024-06-17 00:20:29.63513 INFO::io.R/saveWithID: saving file= test/results/test.coverage.RData
2024-06-17 00:20:29.638175 INFO::coverage.R/saveCoverage: saving file= test/results/test.coverage.bw
2024-06-17 00:20:29.792466 INFO::io.R/saveWithID: saving file= test/results/test.summary_coverage.tab
2024-06-17 00:20:29.795323 INFO::coverage.R/calculateCoverage: done
2024-06-17 00:20:29.797797 INFO::analyzeVariants/analyzeVariants: starting ...
2024-06-17 00:20:29.941885 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-17 00:20:43.272532 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-17 00:20:43.3455 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-17 00:20:43.36148 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-17 00:20:43.362837 INFO::io.R/saveWithID: saving file= test/results/test.raw_variants.RData
2024-06-17 00:20:43.365638 INFO::io.R/saveWithID: saving file= test/results/test.filtered_variants.RData
2024-06-17 00:20:43.367085 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-17 00:20:43.368176 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-17 00:20:43.5847 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-17 00:20:43.681695 INFO::io.R/saveWithID: saving file= test/results/test.summary_variants.tab
2024-06-17 00:20:43.683827 INFO::analyzeVariants/analyzeVariants: done
2024-06-17 00:20:43.690954 INFO::Pipeline run successful.
 done successfully.



Executing test function test.calculateTargetLength  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmpl0EpYe/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-17 00:20:43.939274 INFO::io.R/saveWithID: saving file= /tmp/Rtmpl0EpYe/test.calcTargetLengths.284c915108740a/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 -- Mon Jun 17 00:20:57 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.19-bioc/R/site-library/HTSeqGenie/unitTests 
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.alignReads.R 
test.alignReads: (2 checks) ... OK (25.99 seconds)
test.alignReads.sparsechunks: (2 checks) ... OK (16.24 seconds)
test.alignReadsOneSingleEnd: (2 checks) ... OK (0.53 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.analyzeVariants.R 
test.annotateVariants : DEACTIVATED, Skipped annotateVariants() test
test.callVariantsVariantTools.genotype: (2 checks) ... OK (65.51 seconds)
test.wrap.callVariants: (4 checks) ... OK (9.9 seconds)
test.wrap.callVariants.filters: (2 checks) ... OK (20.17 seconds)
test.wrap.callVariants.which: (1 checks) ... OK (2.79 seconds)
test.writeVCF.NULL: (1 checks) ... OK (0.15 seconds)
test.writeVCF.vcfStat: (4 checks) ... OK (1.75 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.bamUtils.R 
test.isFirstFragment: (5 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.buildGenomicFeatures.R 
test.buildCountsGRangesList: (3 checks) ... OK (25.88 seconds)
test.generateSingleGeneDERs: (4 checks) ... OK (23.23 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.calculateCoverage.R 
test.computeCoverage: (9 checks) ... OK (0.61 seconds)
test.isSparse: (5 checks) ... OK (0.08 seconds)
test.mergeCoverage: (1 checks) ... OK (1.34 seconds)
test.mergeCoverage.sparse: (2 checks) ... OK (1.16 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.checkConfig.R 
test.checkConfig.analyzeVariants: (5 checks) ... OK (0.14 seconds)
test.findTemplate: (5 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.config.R 
test.checkConfig: (5 checks) ... OK (0.31 seconds)
test.checkConfig.alignReads: (5 checks) ... OK (0.35 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.19-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.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.detectRRNA.R 
test.detectRRNA: (1 checks) ... OK (0.44 seconds)
test.detectRRNA.paired_end: (1 checks) ... OK (0.45 seconds)
test.getRRNAIds: (1 checks) ... OK (0.3 seconds)
test.getRRNAIds_random: (1 checks) ... OK (0.24 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-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.04 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-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.15 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.19-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.32 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 (0.54 seconds)
test.createTmpDir: (4 checks) ... OK (0 seconds)
test.detectQualityInFASTQFile: (3 checks) ... OK (0.13 seconds)
test.getObjectFilename: (4 checks) ... OK (0 seconds)
test.safeUnlink: (2 checks) ... OK (0.01 seconds)
test.writeAudit: (0 checks) ... OK (0.17 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.mergeLanes.R 
test.mergeLanes: (6 checks) ... OK (55.88 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-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.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.preprocessReads.R 
test.preprocessReads: (5 checks) ... OK (8.27 seconds)
test.preprocessReads.minichunks: (5 checks) ... OK (13.49 seconds)
test.preprocessReads_single_end: (5 checks) ... OK (6.68 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.readRNASeqEnds.R 
test.readRNASeqEnds: (6 checks) ... OK (0.11 seconds)
test.readRNASeqEnds.dupmark: (2 checks) ... OK (0.08 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.reportPipelineQA.R 
test.how_many: (3 checks) ... OK (0 seconds)
test.plotDF: (3 checks) ... OK (0.12 seconds)
test.relativeBarPlot: (2 checks) ... OK (0.05 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.runPipeline.R 
test.runPipeline: (1 checks) ... OK (60.92 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.targetLengths.R 
test.calculateTargetLength: (4 checks) ... OK (0.25 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.tools.R 
test.sclapply: (10 checks) ... OK (13.46 seconds)
test.tryKeepTraceback: (3 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-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 
241.401  81.892 375.593

Example timings

HTSeqGenie.Rcheck/HTSeqGenie-Ex.timings

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