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

Hostname	OS	Arch (*)	R version	Installed pkgs
nebbiolo1	Linux (Ubuntu 22.04.3 LTS)	x86_64	4.4.1 (2024-06-14) -- "Race for Your Life"	4747
palomino7	Windows Server 2022 Datacenter	x64	4.4.1 (2024-06-14 ucrt) -- "Race for Your Life"	4489
merida1	macOS 12.7.5 Monterey	x86_64	4.4.1 (2024-06-14) -- "Race for Your Life"	4518
kjohnson1	macOS 13.6.6 Ventura	arm64	4.4.1 (2024-06-14) -- "Race for Your Life"	4467
Click on any hostname to see more info about the system (e.g. compilers) () as reported by 'uname -p', except on Windows and Mac OS X*

CHECK results for HTSeqGenie on nebbiolo1

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

raw results

Summary

Package: HTSeqGenie

Version: 4.34.0

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

StartedAt: 2024-07-22 01:18:25 -0400 (Mon, 22 Jul 2024)

EndedAt: 2024-07-22 01:32:22 -0400 (Mon, 22 Jul 2024)

EllapsedTime: 837.0 seconds

RetCode: 0

Status: OK

CheckDir: HTSeqGenie.Rcheck

Warnings: 0

Command output

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


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

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

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

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

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

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

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

Installation output

HTSeqGenie.Rcheck/00install.out

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


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

Tests output

HTSeqGenie.Rcheck/tests/doRUnit.Rout


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

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

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

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

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

Attaching package: 'BiocGenerics'

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

    IQR, mad, sd, var, xtabs

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

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

Loading required package: S4Vectors
Loading required package: stats4

Attaching package: 'S4Vectors'

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

    findMatches

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

    I, expand.grid, unname

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

Attaching package: 'Biostrings'

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

    strsplit

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

Attaching package: 'MatrixGenerics'

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

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

Loading required package: Biobase
Welcome to Bioconductor

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


Attaching package: 'Biobase'

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

    rowMedians

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

    anyMissing, rowMedians

Loading required package: VariantAnnotation

Attaching package: 'VariantAnnotation'

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

    tabulate

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


Executing test function test.alignReads  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:24:12.379763 INFO::preprocessReads.R/preprocessReads: starting...
2024-07-22 01:24:12.389091 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:24:12.392847 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-07-22 01:24:12.395163 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:24:15.407681 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:24:15.409347 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/chunks/chunk_000001/logs/progress.log
2024-07-22 01:24:18.17995 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.046 minutes
2024-07-22 01:24:18.181561 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/chunks/chunk_000002/logs/progress.log
2024-07-22 01:24:20.927002 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.046 minutes
2024-07-22 01:24:20.928312 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/chunks/chunk_000003/logs/progress.log
2024-07-22 01:24:23.66268 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.046 minutes
2024-07-22 01:24:23.696595 DEBUG::tools.R/processChunks: done
2024-07-22 01:24:23.700824 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-07-22 01:24:23.703138 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/results/test_pe.adapter_contaminated_1.RData
2024-07-22 01:24:23.705875 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-07-22 01:24:23.707447 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/results/test_pe.adapter_contaminated_2.RData
2024-07-22 01:24:23.717 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-07-22 01:24:23.719247 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/results/test_pe.summary_preprocess.tab
2024-07-22 01:24:23.722673 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/bams/processed.aligner_input_1.fastq ...
2024-07-22 01:24:23.728268 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/bams/processed.aligner_input_2.fastq ...
2024-07-22 01:24:23.731377 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/reports/shortReadReport_1 ...
2024-07-22 01:24:25.08369 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/reports/shortReadReport_2 ...
2024-07-22 01:24:26.096766 INFO::preprocessReads.R/preprocessReads: done
2024-07-22 01:24:26.173562 INFO::alignReads.R/alignReads: starting alignment...
2024-07-22 01:24:26.179574 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:24:29.216604 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:24:29.218572 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/chunks/chunk_000001/logs/progress.log
2024-07-22 01:24:32.001688 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.046 minutes
2024-07-22 01:24:32.003979 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/chunks/chunk_000002/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-07-22 01:24:34.667976 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.044 minutes
2024-07-22 01:24:34.670081 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/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-07-22 01:24:37.318381 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.044 minutes
2024-07-22 01:24:37.32098 DEBUG::tools.R/processChunks: done
2024-07-22 01:24:37.322464 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "T" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-07-22 01:24:37.540522 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-07-22 01:24:37.549978 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/results/test_pe.summary_alignment.tab
2024-07-22 01:24:37.557578 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/results/test_pe.summary_analyzed_bamstats.tab
2024-07-22 01:24:37.559302 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-07-22 01:24:37.811756 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.alignReads.fe75a349e27d2/results/test_pe.summary_target_lengths.tab
2024-07-22 01:24:37.859819 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-07-22 01:24:37.86108 INFO::alignReads.R/alignReads: done
 done successfully.



Executing test function test.alignReads.sparsechunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:24:38.141524 INFO::preprocessReads.R/preprocessReads: starting...
2024-07-22 01:24:38.145073 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:24:38.220479 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 2 , totnbreads= 26 )
2024-07-22 01:24:38.225595 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:24:38.228752 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-07-22 01:24:38.230877 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:24:41.270241 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:24:41.272148 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmp30uwm2/test.alignReads.sparsechunks.fe75a18908b97/chunks/chunk_000001/logs/progress.log
2024-07-22 01:24:43.960753 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.045 minutes
2024-07-22 01:24:43.962283 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmp30uwm2/test.alignReads.sparsechunks.fe75a18908b97/chunks/chunk_000002/logs/progress.log
2024-07-22 01:24:46.642588 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.045 minutes
2024-07-22 01:24:46.644063 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmp30uwm2/test.alignReads.sparsechunks.fe75a18908b97/chunks/chunk_000003/logs/progress.log
2024-07-22 01:24:49.462271 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.047 minutes
2024-07-22 01:24:49.463911 DEBUG::tools.R/processChunks: starting chunkid= 4 ; see logfile= /tmp/Rtmp30uwm2/test.alignReads.sparsechunks.fe75a18908b97/chunks/chunk_000004/logs/progress.log
2024-07-22 01:24:52.197718 DEBUG::tools.R/processChunks: done with chunkid= 4 ; elapsed.time= 0.046 minutes
2024-07-22 01:24:52.229563 DEBUG::tools.R/processChunks: done
2024-07-22 01:24:52.233263 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-07-22 01:24:52.235761 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.alignReads.sparsechunks.fe75a18908b97/results/test_pe.adapter_contaminated_1.RData
2024-07-22 01:24:52.23875 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-07-22 01:24:52.240508 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.alignReads.sparsechunks.fe75a18908b97/results/test_pe.adapter_contaminated_2.RData
2024-07-22 01:24:52.251199 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-07-22 01:24:52.253724 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.alignReads.sparsechunks.fe75a18908b97/results/test_pe.summary_preprocess.tab
2024-07-22 01:24:52.257569 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmp30uwm2/test.alignReads.sparsechunks.fe75a18908b97/bams/processed.aligner_input_1.fastq ...
2024-07-22 01:24:52.261763 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmp30uwm2/test.alignReads.sparsechunks.fe75a18908b97/bams/processed.aligner_input_2.fastq ...
2024-07-22 01:24:52.265624 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmp30uwm2/test.alignReads.sparsechunks.fe75a18908b97/reports/shortReadReport_1 ...
2024-07-22 01:24:53.544624 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmp30uwm2/test.alignReads.sparsechunks.fe75a18908b97/reports/shortReadReport_2 ...
2024-07-22 01:24:54.521029 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.alignReadsOneSingleEnd  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:24:54.687052 INFO::alignReads.R/alignReadsChunk: running gsnap...
2024-07-22 01:24:54.69223 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/Rtmp30uwm2/test.alignReadsOneSingleEnd.fe75a70648f33/bams/test.alignReads /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq 2>&1
2024-07-22 01:24:54.918671 INFO::alignReads.R/createSummaryAlignment: counting unique bam reads...
2024-07-22 01:24:55.006889 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.alignReadsOneSingleEnd.fe75a70648f33/results/test.alignReads.summary_alignment.tab
2024-07-22 01:24:55.049327 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.alignReadsOneSingleEnd.fe75a70648f33/results/test.alignReads.summary_analyzed_bamstats.tab
2024-07-22 01:24:55.050864 INFO::alignReads.R/alignReadsChunk: done
 done successfully.



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



Executing test function test.callVariantsVariantTools.genotype  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:24:55.358459 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.genotype.fe75a3053ee06/results/test_pe.coverage.RData
2024-07-22 01:24:55.36026 INFO::coverage.R/saveCoverage: saving file= /tmp/Rtmp30uwm2/test.genotype.fe75a3053ee06/results/test_pe.coverage.bw
2024-07-22 01:24:55.473508 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.genotype.fe75a3053ee06/results/test_pe.summary_coverage.tab
2024-07-22 01:24:55.475215 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-07-22 01:25:05.569388 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-07-22 01:25:05.651766 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-07-22 01:25:05.668535 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-07-22 01:25:05.670044 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.genotype.fe75a3053ee06/results/test_pe.raw_variants.RData
2024-07-22 01:25:05.672379 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.genotype.fe75a3053ee06/results/test_pe.filtered_variants.RData
2024-07-22 01:25:05.673666 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-07-22 01:25:05.674824 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-07-22 01:25:06.056403 INFO::analyzeVariants.R/writeVCF: ...done
2024-07-22 01:25:06.057618 INFO::analyzeVariants.R/.callGenotypes: calling genotypes...
2024-07-22 01:26:00.182873 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-07-22 01:26:00.583911 INFO::analyzeVariants.R/writeVCF: ...done
2024-07-22 01:26:00.584895 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/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:26:01.011831 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-07-22 01:26:10.883483 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-07-22 01:26:10.956182 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-07-22 01:26:10.971629 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-07-22 01:26:10.973026 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.wrap.callVariants.fe75a6f685c09/results/test_pe.raw_variants.RData
2024-07-22 01:26:10.975318 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.wrap.callVariants.fe75a6f685c09/results/test_pe.filtered_variants.RData
2024-07-22 01:26:10.976615 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.filters  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:26:11.116669 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-07-22 01:26:21.169635 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-07-22 01:26:21.226138 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-07-22 01:26:21.242338 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-07-22 01:26:21.243695 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.wrap.callVariants.filters.fe75a18a3233c/results/test_pe.raw_variants.RData
2024-07-22 01:26:21.246069 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.wrap.callVariants.filters.fe75a18a3233c/results/test_pe.filtered_variants.RData
2024-07-22 01:26:21.247339 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-07-22 01:26:21.248825 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-07-22 01:26:31.657651 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-07-22 01:26:31.694032 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-07-22 01:26:31.710374 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-07-22 01:26:31.711787 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.wrap.callVariants.filters.fe75a18a3233c/results/test_pe.raw_variants.RData
2024-07-22 01:26:31.714348 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.wrap.callVariants.filters.fe75a18a3233c/results/test_pe.filtered_variants.RData
2024-07-22 01:26:31.716338 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.which  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:26:31.970078 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-07-22 01:26:31.971773 INFO::analyzeVariants.R/buildTallyParam: restricting variant calls using 'which'
2024-07-22 01:26:34.732356 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-07-22 01:26:34.806541 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-07-22 01:26:34.823364 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-07-22 01:26:34.824762 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.wrap.callVariants.which.fe75adf87108/results/test_pe.raw_variants.RData
2024-07-22 01:26:34.826404 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.wrap.callVariants.which.fe75adf87108/results/test_pe.filtered_variants.RData
2024-07-22 01:26:34.827653 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.writeVCF.NULL  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:26:34.97772 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-07-22 01:26:34.978981 INFO::analyzeVariants.R/writeVCF: ...done
 done successfully.



Executing test function test.writeVCF.vcfStat  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:26:36.636827 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-07-22 01:26:36.838899 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-07-22 01:27:30.131182 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/xgqvltkh/merged/results/bla.coverage.RData
2024-07-22 01:27:30.133069 INFO::coverage.R/saveCoverage: saving file= /tmp/Rtmp30uwm2/xgqvltkh/merged/results/bla.coverage.bw
2024-07-22 01:27:30.212868 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/xgqvltkh/merged/results/bla.summary_coverage.tab
 done successfully.



Executing test function test.mergeCoverage.sparse  ... 2024-07-22 01:27:31.324945 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/xeovascm/merged/results/bla.coverage.RData
2024-07-22 01:27:31.326519 INFO::coverage.R/saveCoverage: saving file= /tmp/Rtmp30uwm2/xeovascm/merged/results/bla.coverage.bw
2024-07-22 01:27:31.338259 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/xeovascm/merged/results/bla.summary_coverage.tab
 done successfully.



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



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



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



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



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



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



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



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



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



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



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



Executing test function test.detectRRNA  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:27:32.576943 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-07-22 01:27:32.578077 INFO::io.R/writeFastQFiles: writing filename= /tmp/Rtmp30uwm2/test.detectRRNA.fe75a7204e84b/bams/rRNA_contam/input1.fastq
2024-07-22 01:27:32.581294 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/Rtmp30uwm2/test.detectRRNA.fe75a7204e84b/bams/rRNA_contam/test_se /tmp/Rtmp30uwm2/test.detectRRNA.fe75a7204e84b/bams/rRNA_contam/input1.fastq 2>&1
2024-07-22 01:27:32.847202 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-07-22 01:27:32.848245 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.detectRRNA.paired_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:27:32.996615 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-07-22 01:27:32.997564 INFO::io.R/writeFastQFiles: writing filename= /tmp/Rtmp30uwm2/test.detectRRNA.paired_end.fe75aedaf6ab/bams/rRNA_contam/input1.fastq
2024-07-22 01:27:32.998993 INFO::io.R/writeFastQFiles: writing filename= /tmp/Rtmp30uwm2/test.detectRRNA.paired_end.fe75aedaf6ab/bams/rRNA_contam/input2.fastq
2024-07-22 01:27:33.001103 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/Rtmp30uwm2/test.detectRRNA.paired_end.fe75aedaf6ab/bams/rRNA_contam/test_pe /tmp/Rtmp30uwm2/test.detectRRNA.paired_end.fe75aedaf6ab/bams/rRNA_contam/input1.fastq -a paired /tmp/Rtmp30uwm2/test.detectRRNA.paired_end.fe75aedaf6ab/bams/rRNA_contam/input2.fastq 2>&1
2024-07-22 01:27:33.287034 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-07-22 01:27:33.28804 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.getRRNAIds  ... 2024-07-22 01:27:33.306144 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/Rtmp30uwm2/test_get_rRNA_idsxltzknyp/test_pe /tmp/Rtmp30uwm2/test_get_rRNA_idsxltzknyp/1.fastq -a paired /tmp/Rtmp30uwm2/test_get_rRNA_idsxltzknyp/2.fastq 2>&1
 done successfully.



Executing test function test.getRRNAIds_random  ... 2024-07-22 01:27:33.612025 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/Rtmp30uwm2/test_get_rRNAIds_randomuxjqehnr/test_pe /tmp/Rtmp30uwm2/test_get_rRNAIds_randomuxjqehnr/1.fastq 2>&1
 done successfully.



Executing test function test.filterByLength  ... 2024-07-22 01:27:33.850191 INFO::filterQuality.R/filterQuality: filterByLength...
2024-07-22 01:27:33.851843 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 0.5
2024-07-22 01:27:33.85281 INFO::filterQuality.R/filterByLength: done
2024-07-22 01:27:33.903729 INFO::filterQuality.R/filterQuality: filterByLength...
2024-07-22 01:27:33.904979 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 1
2024-07-22 01:27:33.906003 INFO::filterQuality.R/filterByLength: done
 done successfully.



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



Executing test function test.trimTailsByQuality  ... 2024-07-22 01:27:33.959888 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-07-22 01:27:33.969441 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-07-22 01:27:33.970604 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-07-22 01:27:33.975413 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-07-22 01:27:33.976445 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-07-22 01:27:33.98108 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-07-22 01:27:33.982052 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-07-22 01:27:33.986648 INFO::preprocessReads.R/preprocessReadsChunk: done
 done successfully.



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



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



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



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



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



Executing test function test.realignIndels  ... Timing stopped at: 0 0 0
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/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:27:34.288075 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:27:34.290367 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



Executing test function test.FastQStreamer.getReads.pefq.subsample  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:27:34.467352 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:27:34.568702 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-07-22 01:27:34.571432 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:27:34.573599 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



Executing test function test.FastQStreamer.getReads.segz  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:27:34.805447 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/reads.fastq.gz
 done successfully.



Executing test function test.FastQStreamer.getReads.truncated  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:27:34.946124 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/truncated.fastq.gz
 done successfully.



Executing test function test.FastQStreamer.subsampler.isdeterministic  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:27:35.125356 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:27:35.205974 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-07-22 01:27:35.208655 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:27:35.210916 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:27:35.415952 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:27:35.461591 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-07-22 01:27:35.463943 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:27:35.46604 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



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



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



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



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



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



Executing test function test.mergeLanes  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:27:36.165942 INFO::preprocessReads.R/preprocessReads: starting...
2024-07-22 01:27:36.171839 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:27:36.175298 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-07-22 01:27:36.177509 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:27:38.951484 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:27:38.952854 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/chunks/chunk_000001/logs/progress.log
2024-07-22 01:27:41.53782 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.043 minutes
2024-07-22 01:27:41.539233 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/chunks/chunk_000002/logs/progress.log
2024-07-22 01:27:44.144476 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.043 minutes
2024-07-22 01:27:44.145868 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/chunks/chunk_000003/logs/progress.log
2024-07-22 01:27:46.85856 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.045 minutes
2024-07-22 01:27:46.912498 DEBUG::tools.R/processChunks: done
2024-07-22 01:27:46.916553 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-07-22 01:27:46.918686 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.adapter_contaminated_1.RData
2024-07-22 01:27:46.921137 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-07-22 01:27:46.922899 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.adapter_contaminated_2.RData
2024-07-22 01:27:46.932176 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-07-22 01:27:46.934135 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.summary_preprocess.tab
2024-07-22 01:27:46.936836 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/bams/processed.aligner_input_1.fastq ...
2024-07-22 01:27:46.940898 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/bams/processed.aligner_input_2.fastq ...
2024-07-22 01:27:46.944393 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/reports/shortReadReport_1 ...
2024-07-22 01:27:48.277123 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/reports/shortReadReport_2 ...
2024-07-22 01:27:49.30142 INFO::preprocessReads.R/preprocessReads: done
2024-07-22 01:27:49.382663 INFO::alignReads.R/alignReads: starting alignment...
2024-07-22 01:27:49.387553 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:27:52.358181 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:27:52.360004 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/chunks/chunk_000001/logs/progress.log
2024-07-22 01:27:55.032068 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.045 minutes
2024-07-22 01:27:55.034064 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/chunks/chunk_000002/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-07-22 01:27:57.66598 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.044 minutes
2024-07-22 01:27:57.667519 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/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-07-22 01:28:00.269821 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-07-22 01:28:00.272627 DEBUG::tools.R/processChunks: done
2024-07-22 01:28:00.27437 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "T" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-07-22 01:28:00.473107 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-07-22 01:28:00.481393 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.summary_alignment.tab
2024-07-22 01:28:00.488148 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.summary_analyzed_bamstats.tab
2024-07-22 01:28:00.489994 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-07-22 01:28:00.721416 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.summary_target_lengths.tab
2024-07-22 01:28:00.770241 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-07-22 01:28:00.771528 INFO::alignReads.R/alignReads: done
2024-07-22 01:28:00.849516 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-07-22 01:28:00.870128 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:28:03.962703 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:28:03.964334 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/chunks/chunk_000001/logs/progress.log
2024-07-22 01:28:06.434285 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.041 minutes
2024-07-22 01:28:06.436072 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/chunks/chunk_000002/logs/progress.log
2024-07-22 01:28:08.880359 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.041 minutes
2024-07-22 01:28:08.882109 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/chunks/chunk_000003/logs/progress.log
2024-07-22 01:28:11.326483 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.041 minutes
2024-07-22 01:28:11.32994 DEBUG::tools.R/processChunks: done
2024-07-22 01:28:11.332368 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-07-22 01:28:11.35267 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.counts_exon.tab
2024-07-22 01:28:11.371708 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.counts_exon_disjoint.tab
2024-07-22 01:28:11.382287 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.counts_gene.tab
2024-07-22 01:28:11.388661 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.counts_gene_coding.tab
2024-07-22 01:28:11.394381 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.counts_gene_exonic.tab
2024-07-22 01:28:11.399791 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.counts_intergenic.tab
2024-07-22 01:28:11.409049 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.counts_intron.tab
2024-07-22 01:28:11.412365 INFO::countGenomicFeatures.R/mergeCounts: done
2024-07-22 01:28:11.417556 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.summary_counts.tab
2024-07-22 01:28:11.419103 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-07-22 01:28:11.700702 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-07-22 01:28:11.701591 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-07-22 01:28:11.765466 INFO::coverage.R/calculateCoverage: starting...
2024-07-22 01:28:11.770165 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:28:15.164513 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:28:15.166467 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/chunks/chunk_000001/logs/progress.log
2024-07-22 01:28:17.316587 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.036 minutes
2024-07-22 01:28:17.318113 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/chunks/chunk_000002/logs/progress.log
2024-07-22 01:28:19.4975 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.036 minutes
2024-07-22 01:28:19.500139 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/chunks/chunk_000003/logs/progress.log
2024-07-22 01:28:21.677652 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.036 minutes
2024-07-22 01:28:21.680375 DEBUG::tools.R/processChunks: done
2024-07-22 01:28:23.496502 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.coverage.RData
2024-07-22 01:28:23.498104 INFO::coverage.R/saveCoverage: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.coverage.bw
2024-07-22 01:28:23.509822 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.summary_coverage.tab
2024-07-22 01:28:23.511086 INFO::coverage.R/calculateCoverage: done
2024-07-22 01:28:23.513081 INFO::analyzeVariants/analyzeVariants: starting ...
2024-07-22 01:28:23.60243 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-07-22 01:28:26.716071 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-07-22 01:28:26.782418 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-07-22 01:28:26.797105 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-07-22 01:28:26.798358 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.raw_variants.RData
2024-07-22 01:28:26.799884 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.filtered_variants.RData
2024-07-22 01:28:26.801047 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-07-22 01:28:26.80196 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-07-22 01:28:26.996036 INFO::analyzeVariants.R/writeVCF: ...done
2024-07-22 01:28:27.084302 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/results/test_pe.summary_variants.tab
2024-07-22 01:28:27.086502 INFO::analyzeVariants/analyzeVariants: done
2024-07-22 01:28:27.089812 INFO::Pipeline run successful.
2024-07-22 01:28:27.226631 INFO::mergeLanes.R/doMergeLanes: starting...
2024-07-22 01:28:27.231855 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-07-22 01:28:27.234235 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.adapter_contaminated_1.RData
2024-07-22 01:28:27.237438 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-07-22 01:28:27.239575 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.adapter_contaminated_2.RData
2024-07-22 01:28:27.251862 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-07-22 01:28:27.254301 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.summary_preprocess.tab
2024-07-22 01:28:27.256564 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "T" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-07-22 01:28:27.501073 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-07-22 01:28:27.509214 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.summary_alignment.tab
2024-07-22 01:28:27.517764 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.summary_analyzed_bamstats.tab
2024-07-22 01:28:27.520284 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-07-22 01:28:27.785112 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.summary_target_lengths.tab
2024-07-22 01:28:27.840988 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-07-22 01:28:27.889066 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-07-22 01:28:27.912312 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.counts_exon.tab
2024-07-22 01:28:27.926064 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.counts_exon_disjoint.tab
2024-07-22 01:28:27.933871 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.counts_gene.tab
2024-07-22 01:28:27.93984 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.counts_gene_coding.tab
2024-07-22 01:28:27.945677 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.counts_gene_exonic.tab
2024-07-22 01:28:27.951728 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.counts_intergenic.tab
2024-07-22 01:28:27.963732 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.counts_intron.tab
2024-07-22 01:28:27.967236 INFO::countGenomicFeatures.R/mergeCounts: done
2024-07-22 01:28:27.973896 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.summary_counts.tab
2024-07-22 01:28:27.975849 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-07-22 01:28:28.196401 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-07-22 01:28:30.503486 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.coverage.RData
2024-07-22 01:28:30.508081 INFO::coverage.R/saveCoverage: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.coverage.bw
2024-07-22 01:28:30.524179 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.summary_coverage.tab
2024-07-22 01:28:30.571135 INFO::analyzeVariants/analyzeVariants: starting ...
2024-07-22 01:28:30.654382 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-07-22 01:28:33.742723 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-07-22 01:28:33.810826 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-07-22 01:28:33.826753 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-07-22 01:28:33.828124 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.raw_variants.RData
2024-07-22 01:28:33.8296 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.filtered_variants.RData
2024-07-22 01:28:33.830782 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-07-22 01:28:33.831724 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-07-22 01:28:34.034423 INFO::analyzeVariants.R/writeVCF: ...done
2024-07-22 01:28:34.125946 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.mergeLanes.fe75ab50b755/merged/results/merged.summary_variants.tab
2024-07-22 01:28:34.127865 INFO::analyzeVariants/analyzeVariants: done
2024-07-22 01:28:34.130676 INFO::mergeLanes.R/doMergeLanes: merge lanes successful.
 done successfully.



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



Executing test function test.markDuplicates_w_outfile  ... Timing stopped at: 0 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/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:28:34.458029 INFO::preprocessReads.R/preprocessReads: starting...
2024-07-22 01:28:34.481282 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:28:34.501717 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-07-22 01:28:34.505121 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:28:37.980163 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:28:37.982339 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmp30uwm2/test.preprocessReads.fe75a49515892/chunks/chunk_000001/logs/progress.log
2024-07-22 01:28:40.666061 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.045 minutes
2024-07-22 01:28:40.711825 DEBUG::tools.R/processChunks: done
2024-07-22 01:28:40.714313 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-07-22 01:28:40.715983 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.preprocessReads.fe75a49515892/results/test_pe.adapter_contaminated_1.RData
2024-07-22 01:28:40.71779 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-07-22 01:28:40.719279 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.preprocessReads.fe75a49515892/results/test_pe.adapter_contaminated_2.RData
2024-07-22 01:28:40.72598 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-07-22 01:28:40.727777 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.preprocessReads.fe75a49515892/results/test_pe.summary_preprocess.tab
2024-07-22 01:28:40.729818 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmp30uwm2/test.preprocessReads.fe75a49515892/bams/processed.aligner_input_1.fastq ...
2024-07-22 01:28:40.733028 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmp30uwm2/test.preprocessReads.fe75a49515892/bams/processed.aligner_input_2.fastq ...
2024-07-22 01:28:40.736057 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmp30uwm2/test.preprocessReads.fe75a49515892/reports/shortReadReport_1 ...
2024-07-22 01:28:42.152138 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmp30uwm2/test.preprocessReads.fe75a49515892/reports/shortReadReport_2 ...
2024-07-22 01:28:43.286128 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads.minichunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:28:43.590728 INFO::preprocessReads.R/preprocessReads: starting...
2024-07-22 01:28:43.597923 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:28:43.602093 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-07-22 01:28:43.604855 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:28:47.367646 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:28:47.369179 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmp30uwm2/test.preprocessReads.minichunks.fe75a5f037635/chunks/chunk_000001/logs/progress.log
2024-07-22 01:28:50.004999 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-07-22 01:28:50.00657 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/Rtmp30uwm2/test.preprocessReads.minichunks.fe75a5f037635/chunks/chunk_000002/logs/progress.log
2024-07-22 01:28:52.675688 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.044 minutes
2024-07-22 01:28:52.678183 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/Rtmp30uwm2/test.preprocessReads.minichunks.fe75a5f037635/chunks/chunk_000003/logs/progress.log
2024-07-22 01:28:57.385896 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.078 minutes
2024-07-22 01:28:57.58133 DEBUG::tools.R/processChunks: done
2024-07-22 01:28:57.586819 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-07-22 01:28:57.607366 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.preprocessReads.minichunks.fe75a5f037635/results/test_pe.adapter_contaminated_1.RData
2024-07-22 01:28:57.61202 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-07-22 01:28:57.615328 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.preprocessReads.minichunks.fe75a5f037635/results/test_pe.adapter_contaminated_2.RData
2024-07-22 01:28:57.649434 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-07-22 01:28:57.669994 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.preprocessReads.minichunks.fe75a5f037635/results/test_pe.summary_preprocess.tab
2024-07-22 01:28:57.675611 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmp30uwm2/test.preprocessReads.minichunks.fe75a5f037635/bams/processed.aligner_input_1.fastq ...
2024-07-22 01:28:57.704193 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmp30uwm2/test.preprocessReads.minichunks.fe75a5f037635/bams/processed.aligner_input_2.fastq ...
2024-07-22 01:28:57.730443 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmp30uwm2/test.preprocessReads.minichunks.fe75a5f037635/reports/shortReadReport_1 ...
2024-07-22 01:29:02.531945 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmp30uwm2/test.preprocessReads.minichunks.fe75a5f037635/reports/shortReadReport_2 ...
2024-07-22 01:29:05.921857 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads_single_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:29:06.612852 INFO::preprocessReads.R/preprocessReads: starting...
2024-07-22 01:29:06.686312 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-07-22 01:29:06.709726 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:29:13.767655 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:29:13.770414 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/Rtmp30uwm2/test.preprocessReads_single_end.fe75a2ea9ce76/chunks/chunk_000001/logs/progress.log
2024-07-22 01:29:16.197858 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.04 minutes
2024-07-22 01:29:16.214535 DEBUG::tools.R/processChunks: done
2024-07-22 01:29:16.218709 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-07-22 01:29:16.221482 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.preprocessReads_single_end.fe75a2ea9ce76/results/test_se.adapter_contaminated_1.RData
2024-07-22 01:29:16.233166 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-07-22 01:29:16.236281 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.preprocessReads_single_end.fe75a2ea9ce76/results/test_se.summary_preprocess.tab
2024-07-22 01:29:16.239524 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/Rtmp30uwm2/test.preprocessReads_single_end.fe75a2ea9ce76/bams/processed.aligner_input_1.fastq ...
2024-07-22 01:29:16.244123 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/Rtmp30uwm2/test.preprocessReads_single_end.fe75a2ea9ce76/reports/shortReadReport_1 ...
2024-07-22 01:29:17.624001 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



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



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



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



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



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



Executing test function test.runPipeline  ... checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:29:18.283059 INFO::preprocessReads.R/preprocessReads: starting...
2024-07-22 01:29:18.302167 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_1.fastq.gz
2024-07-22 01:29:18.320289 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_2.fastq.gz
2024-07-22 01:29:18.322981 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:29:24.731727 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:29:24.739097 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-07-22 01:29:28.432901 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.062 minutes
2024-07-22 01:29:28.536787 DEBUG::tools.R/processChunks: done
2024-07-22 01:29:28.54308 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-07-22 01:29:28.54739 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_1.RData
2024-07-22 01:29:28.552221 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-07-22 01:29:28.556058 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_2.RData
2024-07-22 01:29:28.57265 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-07-22 01:29:28.576939 INFO::io.R/saveWithID: saving file= test/results/test.summary_preprocess.tab
2024-07-22 01:29:28.581278 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_1.fastq ...
2024-07-22 01:29:28.589765 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_2.fastq ...
2024-07-22 01:29:28.597725 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_1 ...
2024-07-22 01:29:32.234154 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_2 ...
2024-07-22 01:29:35.436233 INFO::preprocessReads.R/preprocessReads: done
2024-07-22 01:29:35.640758 INFO::alignReads.R/alignReads: starting alignment...
2024-07-22 01:29:35.649182 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:29:41.512592 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:29:41.514693 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-07-22 01:29:46.092639 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.076 minutes
2024-07-22 01:29:46.096134 DEBUG::tools.R/processChunks: done
2024-07-22 01:29:46.098223 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
2024-07-22 01:29:46.147883 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-07-22 01:29:46.156436 INFO::io.R/saveWithID: saving file= test/results/test.summary_alignment.tab
2024-07-22 01:29:46.164309 INFO::io.R/saveWithID: saving file= test/results/test.summary_analyzed_bamstats.tab
2024-07-22 01:29:46.167515 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-07-22 01:29:46.33914 INFO::io.R/saveWithID: saving file= test/results/test.summary_target_lengths.tab
2024-07-22 01:29:46.386618 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-07-22 01:29:46.387654 INFO::alignReads.R/alignReads: done
2024-07-22 01:29:46.519762 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-07-22 01:29:46.540893 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:29:50.165676 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:29:50.16752 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-07-22 01:29:52.786032 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-07-22 01:29:52.788768 DEBUG::tools.R/processChunks: done
2024-07-22 01:29:52.790777 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-07-22 01:29:52.801863 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon.tab
2024-07-22 01:29:52.811223 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon_disjoint.tab
2024-07-22 01:29:52.818208 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene.tab
2024-07-22 01:29:52.822689 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_coding.tab
2024-07-22 01:29:52.826984 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_exonic.tab
2024-07-22 01:29:52.831306 INFO::io.R/saveWithID: saving file= test/results/test.counts_intergenic.tab
2024-07-22 01:29:52.837832 INFO::io.R/saveWithID: saving file= test/results/test.counts_intron.tab
2024-07-22 01:29:52.842002 INFO::countGenomicFeatures.R/mergeCounts: done
2024-07-22 01:29:52.845892 INFO::io.R/saveWithID: saving file= test/results/test.summary_counts.tab
2024-07-22 01:29:52.847815 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-07-22 01:29:53.086071 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-07-22 01:29:53.087223 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-07-22 01:29:53.183122 INFO::coverage.R/calculateCoverage: starting...
2024-07-22 01:29:53.18838 DEBUG::tools.R/processChunks: starting...
2024-07-22 01:29:57.997799 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-07-22 01:29:57.999836 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-07-22 01:30:00.371531 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.04 minutes
2024-07-22 01:30:00.374255 DEBUG::tools.R/processChunks: done
2024-07-22 01:30:02.025756 INFO::io.R/saveWithID: saving file= test/results/test.coverage.RData
2024-07-22 01:30:02.027708 INFO::coverage.R/saveCoverage: saving file= test/results/test.coverage.bw
2024-07-22 01:30:02.105942 INFO::io.R/saveWithID: saving file= test/results/test.summary_coverage.tab
2024-07-22 01:30:02.107427 INFO::coverage.R/calculateCoverage: done
2024-07-22 01:30:02.109051 INFO::analyzeVariants/analyzeVariants: starting ...
2024-07-22 01:30:02.192116 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-07-22 01:30:13.187985 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-07-22 01:30:13.258883 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-07-22 01:30:13.275898 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-07-22 01:30:13.277333 INFO::io.R/saveWithID: saving file= test/results/test.raw_variants.RData
2024-07-22 01:30:13.280155 INFO::io.R/saveWithID: saving file= test/results/test.filtered_variants.RData
2024-07-22 01:30:13.2816 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-07-22 01:30:13.282649 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-07-22 01:30:13.489053 INFO::analyzeVariants.R/writeVCF: ...done
2024-07-22 01:30:13.588033 INFO::io.R/saveWithID: saving file= test/results/test.summary_variants.tab
2024-07-22 01:30:13.590535 INFO::analyzeVariants/analyzeVariants: done
2024-07-22 01:30:13.604599 INFO::Pipeline run successful.
 done successfully.



Executing test function test.calculateTargetLength  ... checkConfig.R/checkConfig.template: loading template config= //tmp/Rtmp30uwm2/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-07-22 01:30:13.874718 INFO::io.R/saveWithID: saving file= /tmp/Rtmp30uwm2/test.calcTargetLengths.fe75a13fc228e/results/test_pe.summary_target_lengths.tab
 done successfully.



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



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



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



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

RUNIT TEST PROTOCOL -- Mon Jul 22 01:30:28 2024 
*********************************************** 
Number of test functions: 61 
Number of deactivated test functions: 10 
Number of errors: 0 
Number of failures: 0 

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



Details 
*************************** 
Test Suite: HTSeqGenie unit testing 
Test function regexp: ^test.+ 
Test file regexp: ^runit.+\.[rR]$ 
Involved directory: 
/home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests 
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.alignReads.R 
test.alignReads: (2 checks) ... OK (26.94 seconds)
test.alignReads.sparsechunks: (2 checks) ... OK (16.65 seconds)
test.alignReadsOneSingleEnd: (2 checks) ... OK (0.53 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.analyzeVariants.R 
test.annotateVariants : DEACTIVATED, Skipped annotateVariants() test
test.callVariantsVariantTools.genotype: (2 checks) ... OK (65.83 seconds)
test.wrap.callVariants: (4 checks) ... OK (10.1 seconds)
test.wrap.callVariants.filters: (2 checks) ... OK (20.74 seconds)
test.wrap.callVariants.which: (1 checks) ... OK (3.11 seconds)
test.writeVCF.NULL: (1 checks) ... OK (0.15 seconds)
test.writeVCF.vcfStat: (4 checks) ... OK (1.95 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.bamUtils.R 
test.isFirstFragment: (5 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.buildGenomicFeatures.R 
test.buildCountsGRangesList: (3 checks) ... OK (26.65 seconds)
test.generateSingleGeneDERs: (4 checks) ... OK (24.45 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.calculateCoverage.R 
test.computeCoverage: (9 checks) ... OK (0.61 seconds)
test.isSparse: (5 checks) ... OK (0.09 seconds)
test.mergeCoverage: (1 checks) ... OK (1.47 seconds)
test.mergeCoverage.sparse: (2 checks) ... OK (1.14 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.checkConfig.R 
test.checkConfig.analyzeVariants: (5 checks) ... OK (0.14 seconds)
test.findTemplate: (5 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.config.R 
test.checkConfig: (5 checks) ... OK (0.31 seconds)
test.checkConfig.alignReads: (5 checks) ... OK (0.38 seconds)
test.getConfig: (14 checks) ... OK (0 seconds)
test.loadConfig: (2 checks) ... OK (0 seconds)
test.parseDCF: (7 checks) ... OK (0 seconds)
test.updateConfig: (1 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.detectAdapterContam.R 
test.getAdapterSeqs: (5 checks) ... OK (0.03 seconds)
test.isAdapter: (5 checks) ... OK (0.12 seconds)
test.isAdapter3.primeEnd: (1 checks) ... OK (0.08 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.detectRRNA.R 
test.detectRRNA: (1 checks) ... OK (0.42 seconds)
test.detectRRNA.paired_end: (1 checks) ... OK (0.44 seconds)
test.getRRNAIds: (1 checks) ... OK (0.3 seconds)
test.getRRNAIds_random: (1 checks) ... OK (0.25 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.filterQuality.R 
test.filterByLength: (2 checks) ... OK (0.06 seconds)
test.isAboveQualityThresh: (3 checks) ... OK (0.04 seconds)
test.trimTailsByQuality: (4 checks) ... OK (0.04 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.gatk.R 
test.callVariantsGATK : DEACTIVATED, callVariantsGATK() tests need gatk.path option set
test.callVariantsGATK.withFiltering : DEACTIVATED, callVariantsGATK() tests need gatk.path option set
test.checkGATKJar : DEACTIVATED, checkGATKJar() test needs gatk.path option set
test.excludeVariantsByRegion: (3 checks) ... OK (0.15 seconds)
test.gatk : DEACTIVATED, gatk() tests need gatk.path option set
test.realignIndels : DEACTIVATED, test.realignIndels() tests need gatk.path option set
test.realignIndelsGATK : DEACTIVATED, realignIndelsGATK() tests need gatk.path option set
test.realignIndelsGATK.parallel : DEACTIVATED, realignIndelsGATK() tests need gatk.path option set
test_zipUp: (3 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.io.R 
test.FastQStreamer.getReads.pefq: (1 checks) ... OK (0.19 seconds)
test.FastQStreamer.getReads.pefq.subsample: (1 checks) ... OK (0.32 seconds)
test.FastQStreamer.getReads.segz: (1 checks) ... OK (0.15 seconds)
test.FastQStreamer.getReads.truncated: (1 checks) ... OK (0.18 seconds)
test.FastQStreamer.subsampler.isdeterministic: (3 checks) ... OK (0.55 seconds)
test.createTmpDir: (4 checks) ... OK (0 seconds)
test.detectQualityInFASTQFile: (3 checks) ... OK (0.14 seconds)
test.getObjectFilename: (4 checks) ... OK (0 seconds)
test.safeUnlink: (2 checks) ... OK (0 seconds)
test.writeAudit: (0 checks) ... OK (0.16 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.mergeLanes.R 
test.mergeLanes: (6 checks) ... OK (58.3 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.picard.R 
test.markDuplicates : DEACTIVATED, Skipped markDuplicates() test
test.markDuplicates_w_outfile : DEACTIVATED, Skipped markDuplicates() test
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.preprocessReads.R 
test.preprocessReads: (5 checks) ... OK (9.13 seconds)
test.preprocessReads.minichunks: (5 checks) ... OK (22.64 seconds)
test.preprocessReads_single_end: (5 checks) ... OK (11.7 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.readRNASeqEnds.R 
test.readRNASeqEnds: (6 checks) ... OK (0.14 seconds)
test.readRNASeqEnds.dupmark: (2 checks) ... OK (0.09 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.reportPipelineQA.R 
test.how_many: (3 checks) ... OK (0 seconds)
test.plotDF: (3 checks) ... OK (0.13 seconds)
test.relativeBarPlot: (2 checks) ... OK (0.05 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.runPipeline.R 
test.runPipeline: (1 checks) ... OK (55.57 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.targetLengths.R 
test.calculateTargetLength: (4 checks) ... OK (0.27 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.tools.R 
test.sclapply: (10 checks) ... OK (14.71 seconds)
test.tryKeepTraceback: (3 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.trimReads.R 
test.truncateReads: (7 checks) ... OK (0.06 seconds)
test.truncateReads.trim5: (15 checks) ... OK (0.15 seconds) 

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

Example timings

HTSeqGenie.Rcheck/HTSeqGenie-Ex.timings

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