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


* using log directory ‘/home/biocbuild/bbs-3.18-bioc/meat/HTSeqGenie.Rcheck’
* using R version 4.3.3 (2024-02-29)
* using platform: x86_64-pc-linux-gnu (64-bit)
* 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.32.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 R 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 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 ... OK
* 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 ... OK
* 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 in ‘inst/doc’ ... OK
* checking running R code from vignettes ...
  ‘HTSeqGenie.Rnw’... OK
 OK
* checking re-building of vignette outputs ... OK
* checking PDF version of manual ... OK
* DONE

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

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


* installing to library ‘/home/biocbuild/bbs-3.18-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)

R version 4.3.3 (2024-02-29) -- "Angel Food Cake"
Copyright (C) 2024 The R Foundation for Statistical Computing
Platform: x86_64-pc-linux-gnu (64-bit)

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, sort, 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/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-15 23:56:56.605123 INFO::preprocessReads.R/preprocessReads: starting...
2024-04-15 23:56:56.61336 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-15 23:56:56.616772 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-04-15 23:56:56.618889 DEBUG::tools.R/processChunks: starting...
2024-04-15 23:56:59.340864 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-15 23:56:59.342374 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/chunks/chunk_000001/logs/progress.log
2024-04-15 23:57:02.137358 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.047 minutes
2024-04-15 23:57:02.139001 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/chunks/chunk_000002/logs/progress.log
2024-04-15 23:57:04.908933 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.046 minutes
2024-04-15 23:57:04.910398 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/chunks/chunk_000003/logs/progress.log
2024-04-15 23:57:07.649312 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.046 minutes
2024-04-15 23:57:07.682132 DEBUG::tools.R/processChunks: done
2024-04-15 23:57:07.686156 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-04-15 23:57:07.688454 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/results/test_pe.adapter_contaminated_1.RData
2024-04-15 23:57:07.691276 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-04-15 23:57:07.692932 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/results/test_pe.adapter_contaminated_2.RData
2024-04-15 23:57:07.702594 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-04-15 23:57:07.704834 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/results/test_pe.summary_preprocess.tab
2024-04-15 23:57:07.708284 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/bams/processed.aligner_input_1.fastq ...
2024-04-15 23:57:07.712194 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/bams/processed.aligner_input_2.fastq ...
2024-04-15 23:57:07.715372 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/reports/shortReadReport_1 ...
2024-04-15 23:57:08.985372 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/reports/shortReadReport_2 ...
2024-04-15 23:57:11.102224 INFO::preprocessReads.R/preprocessReads: done
2024-04-15 23:57:11.145214 INFO::alignReads.R/alignReads: starting alignment...
2024-04-15 23:57:11.151576 DEBUG::tools.R/processChunks: starting...
2024-04-15 23:57:14.030804 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-15 23:57:14.032516 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/chunks/chunk_000001/logs/progress.log
2024-04-15 23:57:16.852167 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.047 minutes
2024-04-15 23:57:16.85373 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/chunks/chunk_000002/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-04-15 23:57:19.454785 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.043 minutes
2024-04-15 23:57:19.456624 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/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-04-15 23:57:22.043707 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-04-15 23:57:22.047989 DEBUG::tools.R/processChunks: done
2024-04-15 23:57:22.050494 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-04-15 23:57:22.283108 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-04-15 23:57:22.291353 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/results/test_pe.summary_alignment.tab
2024-04-15 23:57:22.298245 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/results/test_pe.summary_analyzed_bamstats.tab
2024-04-15 23:57:22.299884 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-04-15 23:57:22.547917 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.alignReads.31cf8628787d56/results/test_pe.summary_target_lengths.tab
2024-04-15 23:57:22.595659 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-04-15 23:57:22.596715 INFO::alignReads.R/alignReads: done
 done successfully.



Executing test function test.alignReads.sparsechunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-15 23:57:22.826283 INFO::preprocessReads.R/preprocessReads: starting...
2024-04-15 23:57:22.82981 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-15 23:57:22.896646 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 2 , totnbreads= 26 )
2024-04-15 23:57:22.901444 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-15 23:57:22.904422 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-04-15 23:57:22.906372 DEBUG::tools.R/processChunks: starting...
2024-04-15 23:57:26.180862 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-15 23:57:26.182604 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmppiyzUy/test.alignReads.sparsechunks.31cf863c27f7e5/chunks/chunk_000001/logs/progress.log
2024-04-15 23:57:28.894693 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.045 minutes
2024-04-15 23:57:28.896185 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmppiyzUy/test.alignReads.sparsechunks.31cf863c27f7e5/chunks/chunk_000002/logs/progress.log
2024-04-15 23:57:31.597803 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.045 minutes
2024-04-15 23:57:31.599195 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmppiyzUy/test.alignReads.sparsechunks.31cf863c27f7e5/chunks/chunk_000003/logs/progress.log
2024-04-15 23:57:34.323585 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.045 minutes
2024-04-15 23:57:34.324911 DEBUG::tools.R/processChunks: starting chunkid= 4 ; see logfile= /tmp/RtmppiyzUy/test.alignReads.sparsechunks.31cf863c27f7e5/chunks/chunk_000004/logs/progress.log
2024-04-15 23:57:37.008528 DEBUG::tools.R/processChunks: done with chunkid= 4 ; elapsed.time= 0.045 minutes
2024-04-15 23:57:37.042934 DEBUG::tools.R/processChunks: done
2024-04-15 23:57:37.046907 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-04-15 23:57:37.049636 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.alignReads.sparsechunks.31cf863c27f7e5/results/test_pe.adapter_contaminated_1.RData
2024-04-15 23:57:37.053158 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-04-15 23:57:37.055242 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.alignReads.sparsechunks.31cf863c27f7e5/results/test_pe.adapter_contaminated_2.RData
2024-04-15 23:57:37.067198 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-04-15 23:57:37.069599 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.alignReads.sparsechunks.31cf863c27f7e5/results/test_pe.summary_preprocess.tab
2024-04-15 23:57:37.073376 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmppiyzUy/test.alignReads.sparsechunks.31cf863c27f7e5/bams/processed.aligner_input_1.fastq ...
2024-04-15 23:57:37.07933 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmppiyzUy/test.alignReads.sparsechunks.31cf863c27f7e5/bams/processed.aligner_input_2.fastq ...
2024-04-15 23:57:37.08259 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmppiyzUy/test.alignReads.sparsechunks.31cf863c27f7e5/reports/shortReadReport_1 ...
2024-04-15 23:57:38.325904 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmppiyzUy/test.alignReads.sparsechunks.31cf863c27f7e5/reports/shortReadReport_2 ...
2024-04-15 23:57:40.440216 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.alignReadsOneSingleEnd  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-15 23:57:40.625103 INFO::alignReads.R/alignReadsChunk: running gsnap...
2024-04-15 23:57:40.629348 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/RtmppiyzUy/test.alignReadsOneSingleEnd.31cf862c486d13/bams/test.alignReads /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq 2>&1
2024-04-15 23:57:40.816031 INFO::alignReads.R/createSummaryAlignment: counting unique bam reads...
2024-04-15 23:57:40.903509 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.alignReadsOneSingleEnd.31cf862c486d13/results/test.alignReads.summary_alignment.tab
2024-04-15 23:57:40.946423 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.alignReadsOneSingleEnd.31cf862c486d13/results/test.alignReads.summary_analyzed_bamstats.tab
2024-04-15 23:57:40.948018 INFO::alignReads.R/alignReadsChunk: done
 done successfully.



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



Executing test function test.callVariantsVariantTools.genotype  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-15 23:57:41.266958 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.genotype.31cf865d792e1/results/test_pe.coverage.RData
2024-04-15 23:57:41.268926 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmppiyzUy/test.genotype.31cf865d792e1/results/test_pe.coverage.bw
2024-04-15 23:57:41.385412 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.genotype.31cf865d792e1/results/test_pe.summary_coverage.tab
2024-04-15 23:57:41.387474 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-04-15 23:57:51.138893 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-04-15 23:57:51.216143 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-04-15 23:57:51.232229 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-04-15 23:57:51.233574 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.genotype.31cf865d792e1/results/test_pe.raw_variants.RData
2024-04-15 23:57:51.235822 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.genotype.31cf865d792e1/results/test_pe.filtered_variants.RData
2024-04-15 23:57:51.23701 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-04-15 23:57:51.238071 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-04-15 23:57:51.609643 INFO::analyzeVariants.R/writeVCF: ...done
2024-04-15 23:57:51.610698 INFO::analyzeVariants.R/.callGenotypes: calling genotypes...
2024-04-15 23:58:34.157489 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-04-15 23:58:34.5898 INFO::analyzeVariants.R/writeVCF: ...done
2024-04-15 23:58:34.590707 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/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-15 23:58:34.993169 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-04-15 23:58:43.954324 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-04-15 23:58:44.014364 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-04-15 23:58:44.0277 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-04-15 23:58:44.028786 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.wrap.callVariants.31cf8614cf24d7/results/test_pe.raw_variants.RData
2024-04-15 23:58:44.030827 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.wrap.callVariants.31cf8614cf24d7/results/test_pe.filtered_variants.RData
2024-04-15 23:58:44.031881 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.filters  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-15 23:58:44.160689 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-04-15 23:58:53.087147 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-04-15 23:58:53.135558 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-04-15 23:58:53.149521 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-04-15 23:58:53.150758 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.wrap.callVariants.filters.31cf862becd34a/results/test_pe.raw_variants.RData
2024-04-15 23:58:53.152952 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.wrap.callVariants.filters.31cf862becd34a/results/test_pe.filtered_variants.RData
2024-04-15 23:58:53.154041 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-04-15 23:58:53.1552 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-04-15 23:59:02.014334 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-04-15 23:59:02.045624 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-04-15 23:59:02.059392 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-04-15 23:59:02.060541 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.wrap.callVariants.filters.31cf862becd34a/results/test_pe.raw_variants.RData
2024-04-15 23:59:02.0628 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.wrap.callVariants.filters.31cf862becd34a/results/test_pe.filtered_variants.RData
2024-04-15 23:59:02.064582 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.which  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-15 23:59:02.214923 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-04-15 23:59:02.216432 INFO::analyzeVariants.R/buildTallyParam: restricting variant calls using 'which'
2024-04-15 23:59:04.086008 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-04-15 23:59:04.153448 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-04-15 23:59:04.16852 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-04-15 23:59:04.169761 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.wrap.callVariants.which.31cf86188e0d32/results/test_pe.raw_variants.RData
2024-04-15 23:59:04.17125 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.wrap.callVariants.which.31cf86188e0d32/results/test_pe.filtered_variants.RData
2024-04-15 23:59:04.172383 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.writeVCF.NULL  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-15 23:59:04.299687 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-04-15 23:59:04.300913 INFO::analyzeVariants.R/writeVCF: ...done
 done successfully.



Executing test function test.writeVCF.vcfStat  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-15 23:59:04.46993 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-04-15 23:59:04.667053 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-04-16 00:00:00.517286 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/ywubegsi/merged/results/bla.coverage.RData
2024-04-16 00:00:00.519767 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmppiyzUy/ywubegsi/merged/results/bla.coverage.bw
2024-04-16 00:00:00.59019 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/ywubegsi/merged/results/bla.summary_coverage.tab
 done successfully.



Executing test function test.mergeCoverage.sparse  ... 2024-04-16 00:00:01.733661 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/rsgjwyfn/merged/results/bla.coverage.RData
2024-04-16 00:00:01.735349 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmppiyzUy/rsgjwyfn/merged/results/bla.coverage.bw
2024-04-16 00:00:01.746804 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/rsgjwyfn/merged/results/bla.summary_coverage.tab
 done successfully.



Executing test function test.checkConfig.analyzeVariants  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-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/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-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/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-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/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:00:02.925698 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-04-16 00:00:02.926833 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmppiyzUy/test.detectRRNA.31cf861f445fa6/bams/rRNA_contam/input1.fastq
2024-04-16 00:00:02.929919 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/RtmppiyzUy/test.detectRRNA.31cf861f445fa6/bams/rRNA_contam/test_se /tmp/RtmppiyzUy/test.detectRRNA.31cf861f445fa6/bams/rRNA_contam/input1.fastq 2>&1
2024-04-16 00:00:03.058369 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-04-16 00:00:03.059324 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.detectRRNA.paired_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:00:03.20202 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-04-16 00:00:03.202961 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmppiyzUy/test.detectRRNA.paired_end.31cf8632cdddfc/bams/rRNA_contam/input1.fastq
2024-04-16 00:00:03.204401 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmppiyzUy/test.detectRRNA.paired_end.31cf8632cdddfc/bams/rRNA_contam/input2.fastq
2024-04-16 00:00:03.206538 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/RtmppiyzUy/test.detectRRNA.paired_end.31cf8632cdddfc/bams/rRNA_contam/test_pe /tmp/RtmppiyzUy/test.detectRRNA.paired_end.31cf8632cdddfc/bams/rRNA_contam/input1.fastq -a paired /tmp/RtmppiyzUy/test.detectRRNA.paired_end.31cf8632cdddfc/bams/rRNA_contam/input2.fastq 2>&1
2024-04-16 00:00:03.428313 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-04-16 00:00:03.429292 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.getRRNAIds  ... 2024-04-16 00:00:03.448324 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/RtmppiyzUy/test_get_rRNA_idsyznxkasw/test_pe /tmp/RtmppiyzUy/test_get_rRNA_idsyznxkasw/1.fastq -a paired /tmp/RtmppiyzUy/test_get_rRNA_idsyznxkasw/2.fastq 2>&1
 done successfully.



Executing test function test.getRRNAIds_random  ... 2024-04-16 00:00:03.694446 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/RtmppiyzUy/test_get_rRNAIds_randomnsmbqidy/test_pe /tmp/RtmppiyzUy/test_get_rRNAIds_randomnsmbqidy/1.fastq 2>&1
 done successfully.



Executing test function test.filterByLength  ... 2024-04-16 00:00:03.90127 INFO::filterQuality.R/filterQuality: filterByLength...
2024-04-16 00:00:03.903358 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 0.5
2024-04-16 00:00:03.904678 INFO::filterQuality.R/filterByLength: done
2024-04-16 00:00:03.972001 INFO::filterQuality.R/filterQuality: filterByLength...
2024-04-16 00:00:03.972955 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 1
2024-04-16 00:00:03.973768 INFO::filterQuality.R/filterByLength: done
 done successfully.



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



Executing test function test.trimTailsByQuality  ... 2024-04-16 00:00:04.021487 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-04-16 00:00:04.029826 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-04-16 00:00:04.030816 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-04-16 00:00:04.034894 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-04-16 00:00:04.035769 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-04-16 00:00:04.039748 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-04-16 00:00:04.040612 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-04-16 00:00:04.044588 INFO::preprocessReads.R/preprocessReadsChunk: done
 done successfully.



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



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



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



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



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



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



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



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



Executing test function test_zipUp  ...  done successfully.



Executing test function test.FastQStreamer.getReads.pefq  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:00:04.31902 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-16 00:00:04.321259 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-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/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:00:04.485435 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-16 00:00:04.580514 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-04-16 00:00:04.583244 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-16 00:00:04.585308 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-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/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:00:04.790384 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-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/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:00:04.931703 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-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/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:00:05.083522 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-16 00:00:05.140187 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-04-16 00:00:05.142632 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-16 00:00:05.144702 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:00:05.337448 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-16 00:00:05.374015 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-04-16 00:00:05.376424 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-16 00:00:05.378565 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-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/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
 done successfully.



Executing test function test.mergeLanes  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:00:06.042593 INFO::preprocessReads.R/preprocessReads: starting...
2024-04-16 00:00:06.049193 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-16 00:00:06.05288 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-04-16 00:00:06.055354 DEBUG::tools.R/processChunks: starting...
2024-04-16 00:00:09.236377 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-16 00:00:09.238177 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/chunks/chunk_000001/logs/progress.log
2024-04-16 00:00:11.890451 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-04-16 00:00:11.892022 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/chunks/chunk_000002/logs/progress.log
2024-04-16 00:00:14.555751 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.044 minutes
2024-04-16 00:00:14.557183 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/chunks/chunk_000003/logs/progress.log
2024-04-16 00:00:17.34761 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.046 minutes
2024-04-16 00:00:17.382497 DEBUG::tools.R/processChunks: done
2024-04-16 00:00:17.385273 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-04-16 00:00:17.387014 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.adapter_contaminated_1.RData
2024-04-16 00:00:17.389218 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-04-16 00:00:17.390825 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.adapter_contaminated_2.RData
2024-04-16 00:00:17.399852 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-04-16 00:00:17.401807 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.summary_preprocess.tab
2024-04-16 00:00:17.404334 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/bams/processed.aligner_input_1.fastq ...
2024-04-16 00:00:17.408179 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/bams/processed.aligner_input_2.fastq ...
2024-04-16 00:00:17.411379 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/reports/shortReadReport_1 ...
2024-04-16 00:00:18.717017 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/reports/shortReadReport_2 ...
2024-04-16 00:00:19.717542 INFO::preprocessReads.R/preprocessReads: done
2024-04-16 00:00:19.786178 INFO::alignReads.R/alignReads: starting alignment...
2024-04-16 00:00:19.791108 DEBUG::tools.R/processChunks: starting...
2024-04-16 00:00:22.598579 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-16 00:00:22.600292 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/chunks/chunk_000001/logs/progress.log
2024-04-16 00:00:25.12298 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.042 minutes
2024-04-16 00:00:25.125458 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/chunks/chunk_000002/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-04-16 00:00:27.680842 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.043 minutes
2024-04-16 00:00:27.682478 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/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-04-16 00:00:30.222617 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.042 minutes
2024-04-16 00:00:30.225051 DEBUG::tools.R/processChunks: done
2024-04-16 00:00:30.226571 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-04-16 00:00:30.405985 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-04-16 00:00:30.413078 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.summary_alignment.tab
2024-04-16 00:00:30.419404 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.summary_analyzed_bamstats.tab
2024-04-16 00:00:30.421137 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-04-16 00:00:30.659509 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.summary_target_lengths.tab
2024-04-16 00:00:30.704681 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-04-16 00:00:30.705623 INFO::alignReads.R/alignReads: done
2024-04-16 00:00:30.78024 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-04-16 00:00:30.797676 DEBUG::tools.R/processChunks: starting...
2024-04-16 00:00:33.595725 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-16 00:00:33.597464 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/chunks/chunk_000001/logs/progress.log
2024-04-16 00:00:36.024755 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.04 minutes
2024-04-16 00:00:36.026567 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/chunks/chunk_000002/logs/progress.log
2024-04-16 00:00:38.454237 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.04 minutes
2024-04-16 00:00:38.455856 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/chunks/chunk_000003/logs/progress.log
2024-04-16 00:00:40.880376 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.04 minutes
2024-04-16 00:00:40.884208 DEBUG::tools.R/processChunks: done
2024-04-16 00:00:40.886808 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-04-16 00:00:40.907177 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.counts_exon.tab
2024-04-16 00:00:40.924888 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.counts_exon_disjoint.tab
2024-04-16 00:00:40.934311 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.counts_gene.tab
2024-04-16 00:00:40.940349 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.counts_gene_coding.tab
2024-04-16 00:00:40.945977 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.counts_gene_exonic.tab
2024-04-16 00:00:40.951417 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.counts_intergenic.tab
2024-04-16 00:00:40.960633 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.counts_intron.tab
2024-04-16 00:00:40.963967 INFO::countGenomicFeatures.R/mergeCounts: done
2024-04-16 00:00:40.969639 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.summary_counts.tab
2024-04-16 00:00:40.971251 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-04-16 00:00:41.255729 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-04-16 00:00:41.256692 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-04-16 00:00:41.33124 INFO::coverage.R/calculateCoverage: starting...
2024-04-16 00:00:41.336301 DEBUG::tools.R/processChunks: starting...
2024-04-16 00:00:44.279998 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-16 00:00:44.281838 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/chunks/chunk_000001/logs/progress.log
2024-04-16 00:00:46.473342 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.037 minutes
2024-04-16 00:00:46.475083 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/chunks/chunk_000002/logs/progress.log
2024-04-16 00:00:48.643457 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.036 minutes
2024-04-16 00:00:48.645703 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/chunks/chunk_000003/logs/progress.log
2024-04-16 00:00:50.804629 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.036 minutes
2024-04-16 00:00:50.80801 DEBUG::tools.R/processChunks: done
2024-04-16 00:00:52.196234 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.coverage.RData
2024-04-16 00:00:52.197629 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.coverage.bw
2024-04-16 00:00:52.208663 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.summary_coverage.tab
2024-04-16 00:00:52.209887 INFO::coverage.R/calculateCoverage: done
2024-04-16 00:00:52.2118 INFO::analyzeVariants/analyzeVariants: starting ...
2024-04-16 00:00:52.323771 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-04-16 00:00:54.977789 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-04-16 00:00:55.038175 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-04-16 00:00:55.051736 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-04-16 00:00:55.052864 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.raw_variants.RData
2024-04-16 00:00:55.054231 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.filtered_variants.RData
2024-04-16 00:00:55.055295 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-04-16 00:00:55.056121 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-04-16 00:00:55.247107 INFO::analyzeVariants.R/writeVCF: ...done
2024-04-16 00:00:55.33167 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/results/test_pe.summary_variants.tab
2024-04-16 00:00:55.333792 INFO::analyzeVariants/analyzeVariants: done
2024-04-16 00:00:55.33796 INFO::Pipeline run successful.
2024-04-16 00:00:55.498072 INFO::mergeLanes.R/doMergeLanes: starting...
2024-04-16 00:00:55.503054 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-04-16 00:00:55.50519 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.adapter_contaminated_1.RData
2024-04-16 00:00:55.508082 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-04-16 00:00:55.510071 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.adapter_contaminated_2.RData
2024-04-16 00:00:55.522076 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-04-16 00:00:55.524386 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.summary_preprocess.tab
2024-04-16 00:00:55.526605 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-04-16 00:00:55.7593 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-04-16 00:00:55.766958 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.summary_alignment.tab
2024-04-16 00:00:55.775362 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.summary_analyzed_bamstats.tab
2024-04-16 00:00:55.777506 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-04-16 00:00:56.032513 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.summary_target_lengths.tab
2024-04-16 00:00:56.082363 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-04-16 00:00:56.11557 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-04-16 00:00:56.137034 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.counts_exon.tab
2024-04-16 00:00:56.150602 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.counts_exon_disjoint.tab
2024-04-16 00:00:56.158414 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.counts_gene.tab
2024-04-16 00:00:56.164069 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.counts_gene_coding.tab
2024-04-16 00:00:56.169718 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.counts_gene_exonic.tab
2024-04-16 00:00:56.175715 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.counts_intergenic.tab
2024-04-16 00:00:56.18737 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.counts_intron.tab
2024-04-16 00:00:56.190921 INFO::countGenomicFeatures.R/mergeCounts: done
2024-04-16 00:00:56.197666 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.summary_counts.tab
2024-04-16 00:00:56.199515 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-04-16 00:00:56.415478 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-04-16 00:00:58.472497 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.coverage.RData
2024-04-16 00:00:58.475734 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.coverage.bw
2024-04-16 00:00:58.488528 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.summary_coverage.tab
2024-04-16 00:00:58.523188 INFO::analyzeVariants/analyzeVariants: starting ...
2024-04-16 00:00:58.583351 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-04-16 00:01:01.048355 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-04-16 00:01:01.109952 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-04-16 00:01:01.123415 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-04-16 00:01:01.124547 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.raw_variants.RData
2024-04-16 00:01:01.125895 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.filtered_variants.RData
2024-04-16 00:01:01.126947 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-04-16 00:01:01.127766 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-04-16 00:01:01.317682 INFO::analyzeVariants.R/writeVCF: ...done
2024-04-16 00:01:01.404265 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.mergeLanes.31cf867eb731c5/merged/results/merged.summary_variants.tab
2024-04-16 00:01:01.406435 INFO::analyzeVariants/analyzeVariants: done
2024-04-16 00:01:01.409565 INFO::mergeLanes.R/doMergeLanes: merge lanes successful.
 done successfully.



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



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



Executing test function test.preprocessReads  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:01:01.742714 INFO::preprocessReads.R/preprocessReads: starting...
2024-04-16 00:01:01.757722 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-16 00:01:01.770576 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-04-16 00:01:01.773298 DEBUG::tools.R/processChunks: starting...
2024-04-16 00:01:04.631277 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-16 00:01:04.632798 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmppiyzUy/test.preprocessReads.31cf8617a0e1bd/chunks/chunk_000001/logs/progress.log
2024-04-16 00:01:07.282897 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-04-16 00:01:07.329941 DEBUG::tools.R/processChunks: done
2024-04-16 00:01:07.332949 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-04-16 00:01:07.335215 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.preprocessReads.31cf8617a0e1bd/results/test_pe.adapter_contaminated_1.RData
2024-04-16 00:01:07.337149 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-04-16 00:01:07.338701 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.preprocessReads.31cf8617a0e1bd/results/test_pe.adapter_contaminated_2.RData
2024-04-16 00:01:07.345909 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-04-16 00:01:07.347864 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.preprocessReads.31cf8617a0e1bd/results/test_pe.summary_preprocess.tab
2024-04-16 00:01:07.349969 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmppiyzUy/test.preprocessReads.31cf8617a0e1bd/bams/processed.aligner_input_1.fastq ...
2024-04-16 00:01:07.353474 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmppiyzUy/test.preprocessReads.31cf8617a0e1bd/bams/processed.aligner_input_2.fastq ...
2024-04-16 00:01:07.356595 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmppiyzUy/test.preprocessReads.31cf8617a0e1bd/reports/shortReadReport_1 ...
2024-04-16 00:01:08.660359 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmppiyzUy/test.preprocessReads.31cf8617a0e1bd/reports/shortReadReport_2 ...
2024-04-16 00:01:09.644233 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads.minichunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:01:09.908969 INFO::preprocessReads.R/preprocessReads: starting...
2024-04-16 00:01:09.915952 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-16 00:01:09.919827 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-04-16 00:01:09.922444 DEBUG::tools.R/processChunks: starting...
2024-04-16 00:01:13.019515 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-16 00:01:13.021026 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmppiyzUy/test.preprocessReads.minichunks.31cf8638272fe3/chunks/chunk_000001/logs/progress.log
2024-04-16 00:01:15.636574 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-04-16 00:01:15.638319 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmppiyzUy/test.preprocessReads.minichunks.31cf8638272fe3/chunks/chunk_000002/logs/progress.log
2024-04-16 00:01:18.261982 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.044 minutes
2024-04-16 00:01:18.263361 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmppiyzUy/test.preprocessReads.minichunks.31cf8638272fe3/chunks/chunk_000003/logs/progress.log
2024-04-16 00:01:20.859856 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-04-16 00:01:20.887409 DEBUG::tools.R/processChunks: done
2024-04-16 00:01:20.890008 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-04-16 00:01:20.891581 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.preprocessReads.minichunks.31cf8638272fe3/results/test_pe.adapter_contaminated_1.RData
2024-04-16 00:01:20.893562 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-04-16 00:01:20.89502 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.preprocessReads.minichunks.31cf8638272fe3/results/test_pe.adapter_contaminated_2.RData
2024-04-16 00:01:20.902735 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-04-16 00:01:20.904334 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.preprocessReads.minichunks.31cf8638272fe3/results/test_pe.summary_preprocess.tab
2024-04-16 00:01:20.906535 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmppiyzUy/test.preprocessReads.minichunks.31cf8638272fe3/bams/processed.aligner_input_1.fastq ...
2024-04-16 00:01:20.910126 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmppiyzUy/test.preprocessReads.minichunks.31cf8638272fe3/bams/processed.aligner_input_2.fastq ...
2024-04-16 00:01:20.912877 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmppiyzUy/test.preprocessReads.minichunks.31cf8638272fe3/reports/shortReadReport_1 ...
2024-04-16 00:01:22.150367 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmppiyzUy/test.preprocessReads.minichunks.31cf8638272fe3/reports/shortReadReport_2 ...
2024-04-16 00:01:23.12503 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads_single_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:01:23.350145 INFO::preprocessReads.R/preprocessReads: starting...
2024-04-16 00:01:23.365353 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-04-16 00:01:23.367904 DEBUG::tools.R/processChunks: starting...
2024-04-16 00:01:26.25 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-16 00:01:26.251433 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmppiyzUy/test.preprocessReads_single_end.31cf86500353ea/chunks/chunk_000001/logs/progress.log
2024-04-16 00:01:28.629208 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.04 minutes
2024-04-16 00:01:28.639248 DEBUG::tools.R/processChunks: done
2024-04-16 00:01:28.641827 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-04-16 00:01:28.643469 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.preprocessReads_single_end.31cf86500353ea/results/test_se.adapter_contaminated_1.RData
2024-04-16 00:01:28.65047 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-04-16 00:01:28.652278 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.preprocessReads_single_end.31cf86500353ea/results/test_se.summary_preprocess.tab
2024-04-16 00:01:28.654309 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmppiyzUy/test.preprocessReads_single_end.31cf86500353ea/bams/processed.aligner_input_1.fastq ...
2024-04-16 00:01:28.657706 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmppiyzUy/test.preprocessReads_single_end.31cf86500353ea/reports/shortReadReport_1 ...
2024-04-16 00:01:29.931055 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.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:01:30.553652 INFO::preprocessReads.R/preprocessReads: starting...
2024-04-16 00:01:30.56058 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_1.fastq.gz
2024-04-16 00:01:30.564954 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_2.fastq.gz
2024-04-16 00:01:30.567503 DEBUG::tools.R/processChunks: starting...
2024-04-16 00:01:34.289256 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-16 00:01:34.290763 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-04-16 00:01:37.08051 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.046 minutes
2024-04-16 00:01:37.115918 DEBUG::tools.R/processChunks: done
2024-04-16 00:01:37.118238 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-04-16 00:01:37.119726 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_1.RData
2024-04-16 00:01:37.121392 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-04-16 00:01:37.122761 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_2.RData
2024-04-16 00:01:37.128985 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-04-16 00:01:37.130731 INFO::io.R/saveWithID: saving file= test/results/test.summary_preprocess.tab
2024-04-16 00:01:37.132622 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_1.fastq ...
2024-04-16 00:01:37.137256 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_2.fastq ...
2024-04-16 00:01:37.141248 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_1 ...
2024-04-16 00:01:38.495035 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_2 ...
2024-04-16 00:01:39.715936 INFO::preprocessReads.R/preprocessReads: done
2024-04-16 00:01:39.804436 INFO::alignReads.R/alignReads: starting alignment...
2024-04-16 00:01:39.809628 DEBUG::tools.R/processChunks: starting...
2024-04-16 00:01:42.970561 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-16 00:01:42.97281 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-04-16 00:01:47.518619 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.076 minutes
2024-04-16 00:01:47.522534 DEBUG::tools.R/processChunks: done
2024-04-16 00:01:47.524674 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
2024-04-16 00:01:47.561543 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-04-16 00:01:47.568565 INFO::io.R/saveWithID: saving file= test/results/test.summary_alignment.tab
2024-04-16 00:01:47.574222 INFO::io.R/saveWithID: saving file= test/results/test.summary_analyzed_bamstats.tab
2024-04-16 00:01:47.576358 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-04-16 00:01:47.734721 INFO::io.R/saveWithID: saving file= test/results/test.summary_target_lengths.tab
2024-04-16 00:01:47.782016 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-04-16 00:01:47.783077 INFO::alignReads.R/alignReads: done
2024-04-16 00:01:47.874392 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-04-16 00:01:47.892717 DEBUG::tools.R/processChunks: starting...
2024-04-16 00:01:54.111124 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-16 00:01:54.114461 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-04-16 00:01:57.326035 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.053 minutes
2024-04-16 00:01:57.331105 DEBUG::tools.R/processChunks: done
2024-04-16 00:01:57.334329 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-04-16 00:01:57.370079 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon.tab
2024-04-16 00:01:57.416121 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon_disjoint.tab
2024-04-16 00:01:57.440654 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene.tab
2024-04-16 00:01:57.457055 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_coding.tab
2024-04-16 00:01:57.482164 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_exonic.tab
2024-04-16 00:01:57.489082 INFO::io.R/saveWithID: saving file= test/results/test.counts_intergenic.tab
2024-04-16 00:01:57.521308 INFO::io.R/saveWithID: saving file= test/results/test.counts_intron.tab
2024-04-16 00:01:57.527978 INFO::countGenomicFeatures.R/mergeCounts: done
2024-04-16 00:01:57.547683 INFO::io.R/saveWithID: saving file= test/results/test.summary_counts.tab
2024-04-16 00:01:57.567417 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-04-16 00:01:58.10126 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-04-16 00:01:58.102796 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-04-16 00:01:58.426309 INFO::coverage.R/calculateCoverage: starting...
2024-04-16 00:01:58.433837 DEBUG::tools.R/processChunks: starting...
2024-04-16 00:02:05.066817 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-04-16 00:02:05.071582 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-04-16 00:02:08.116271 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.051 minutes
2024-04-16 00:02:08.121195 DEBUG::tools.R/processChunks: done
2024-04-16 00:02:12.459529 INFO::io.R/saveWithID: saving file= test/results/test.coverage.RData
2024-04-16 00:02:12.463535 INFO::coverage.R/saveCoverage: saving file= test/results/test.coverage.bw
2024-04-16 00:02:12.651427 INFO::io.R/saveWithID: saving file= test/results/test.summary_coverage.tab
2024-04-16 00:02:12.654705 INFO::coverage.R/calculateCoverage: done
2024-04-16 00:02:12.657385 INFO::analyzeVariants/analyzeVariants: starting ...
2024-04-16 00:02:12.774345 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-04-16 00:02:24.890199 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-04-16 00:02:25.028557 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-04-16 00:02:25.052333 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-04-16 00:02:25.054355 INFO::io.R/saveWithID: saving file= test/results/test.raw_variants.RData
2024-04-16 00:02:25.059467 INFO::io.R/saveWithID: saving file= test/results/test.filtered_variants.RData
2024-04-16 00:02:25.061786 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-04-16 00:02:25.063387 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-04-16 00:02:25.473672 INFO::analyzeVariants.R/writeVCF: ...done
2024-04-16 00:02:25.665268 INFO::io.R/saveWithID: saving file= test/results/test.summary_variants.tab
2024-04-16 00:02:25.669747 INFO::analyzeVariants/analyzeVariants: done
2024-04-16 00:02:25.681591 INFO::Pipeline run successful.
 done successfully.



Executing test function test.calculateTargetLength  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmppiyzUy/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-04-16 00:02:26.148046 INFO::io.R/saveWithID: saving file= /tmp/RtmppiyzUy/test.calcTargetLengths.31cf864ebe1959/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 -- Tue Apr 16 00:02:51 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.18-bioc/R/site-library/HTSeqGenie/unitTests 
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.alignReads.R 
test.alignReads: (2 checks) ... OK (27.53 seconds)
test.alignReads.sparsechunks: (2 checks) ... OK (17.84 seconds)
test.alignReadsOneSingleEnd: (2 checks) ... OK (0.5 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.analyzeVariants.R 
test.annotateVariants : DEACTIVATED, Skipped annotateVariants() test
test.callVariantsVariantTools.genotype: (2 checks) ... OK (53.91 seconds)
test.wrap.callVariants: (4 checks) ... OK (9.17 seconds)
test.wrap.callVariants.filters: (2 checks) ... OK (18.03 seconds)
test.wrap.callVariants.which: (1 checks) ... OK (2.11 seconds)
test.writeVCF.NULL: (1 checks) ... OK (0.13 seconds)
test.writeVCF.vcfStat: (4 checks) ... OK (0.45 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.bamUtils.R 
test.isFirstFragment: (5 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.buildGenomicFeatures.R 
test.buildCountsGRangesList: (3 checks) ... OK (27.9 seconds)
test.generateSingleGeneDERs: (4 checks) ... OK (25.94 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.calculateCoverage.R 
test.computeCoverage: (9 checks) ... OK (0.63 seconds)
test.isSparse: (5 checks) ... OK (0.09 seconds)
test.mergeCoverage: (1 checks) ... OK (1.28 seconds)
test.mergeCoverage.sparse: (2 checks) ... OK (1.18 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.checkConfig.R 
test.checkConfig.analyzeVariants: (5 checks) ... OK (0.15 seconds)
test.findTemplate: (5 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.config.R 
test.checkConfig: (5 checks) ... OK (0.3 seconds)
test.checkConfig.alignReads: (5 checks) ... OK (0.33 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.18-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.08 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.detectRRNA.R 
test.detectRRNA: (1 checks) ... OK (0.27 seconds)
test.detectRRNA.paired_end: (1 checks) ... OK (0.37 seconds)
test.getRRNAIds: (1 checks) ... OK (0.25 seconds)
test.getRRNAIds_random: (1 checks) ... OK (0.22 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.filterQuality.R 
test.filterByLength: (2 checks) ... OK (0.08 seconds)
test.isAboveQualityThresh: (3 checks) ... OK (0.04 seconds)
test.trimTailsByQuality: (4 checks) ... OK (0.03 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.gatk.R 
test.callVariantsGATK : DEACTIVATED, callVariantsGATK() tests need gatk.path option set
test.callVariantsGATK.withFiltering : DEACTIVATED, callVariantsGATK() tests need gatk.path option set
test.checkGATKJar : DEACTIVATED, checkGATKJar() test needs gatk.path option set
test.excludeVariantsByRegion: (3 checks) ... OK (0.14 seconds)
test.gatk : DEACTIVATED, gatk() tests need gatk.path option set
test.realignIndels : DEACTIVATED, test.realignIndels() tests need gatk.path option set
test.realignIndelsGATK : DEACTIVATED, realignIndelsGATK() tests need gatk.path option set
test.realignIndelsGATK.parallel : DEACTIVATED, realignIndelsGATK() tests need gatk.path option set
test_zipUp: (3 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.io.R 
test.FastQStreamer.getReads.pefq: (1 checks) ... OK (0.17 seconds)
test.FastQStreamer.getReads.pefq.subsample: (1 checks) ... OK (0.3 seconds)
test.FastQStreamer.getReads.segz: (1 checks) ... OK (0.15 seconds)
test.FastQStreamer.getReads.truncated: (1 checks) ... OK (0.16 seconds)
test.FastQStreamer.subsampler.isdeterministic: (3 checks) ... OK (0.48 seconds)
test.createTmpDir: (4 checks) ... OK (0 seconds)
test.detectQualityInFASTQFile: (3 checks) ... OK (0.11 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.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.mergeLanes.R 
test.mergeLanes: (6 checks) ... OK (55.7 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-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.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.preprocessReads.R 
test.preprocessReads: (5 checks) ... OK (8.2 seconds)
test.preprocessReads.minichunks: (5 checks) ... OK (13.48 seconds)
test.preprocessReads_single_end: (5 checks) ... OK (6.81 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.readRNASeqEnds.R 
test.readRNASeqEnds: (6 checks) ... OK (0.11 seconds)
test.readRNASeqEnds.dupmark: (2 checks) ... OK (0.1 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.reportPipelineQA.R 
test.how_many: (3 checks) ... OK (0 seconds)
test.plotDF: (3 checks) ... OK (0.13 seconds)
test.relativeBarPlot: (2 checks) ... OK (0.05 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.runPipeline.R 
test.runPipeline: (1 checks) ... OK (55.35 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.targetLengths.R 
test.calculateTargetLength: (4 checks) ... OK (0.46 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.tools.R 
test.sclapply: (10 checks) ... OK (24.98 seconds)
test.tryKeepTraceback: (3 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.18-bioc/R/site-library/HTSeqGenie/unitTests/runit.trimReads.R 
test.truncateReads: (7 checks) ... OK (0.05 seconds)
test.truncateReads.trim5: (15 checks) ... OK (0.17 seconds) 

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