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

Hostname	OS	Arch (*)	R version	Installed pkgs
teran2	Linux (Ubuntu 24.04.1 LTS)	x86_64	4.4.1 (2024-06-14) -- "Race for Your Life"	4451
nebbiolo2	Linux (Ubuntu 22.04.3 LTS)	x86_64	4.4.1 (2024-06-14) -- "Race for Your Life"	4417
palomino8	Windows Server 2022 Datacenter	x64	4.4.1 (2024-06-14 ucrt) -- "Race for Your Life"	4456
lconway	macOS 12.7.1 Monterey	x86_64	4.4.1 (2024-06-14) -- "Race for Your Life"	4489
kjohnson3	macOS 13.6.5 Ventura	arm64	4.4.1 (2024-06-14) -- "Race for Your Life"	4436
kunpeng2	Linux (openEuler 22.03 LTS-SP1)	aarch64	4.4.1 (2024-06-14) -- "Race for Your Life"	4435
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 teran2

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

raw results

Summary

Package: HTSeqGenie

Version: 4.35.0

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

StartedAt: 2024-09-27 02:36:54 -0400 (Fri, 27 Sep 2024)

EndedAt: 2024-09-27 03:16:54 -0400 (Fri, 27 Sep 2024)

EllapsedTime: 2400.6 seconds

RetCode: None

Status: TIMEOUT

CheckDir: HTSeqGenie.Rcheck

Warnings: NA

Command output

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


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

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

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

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

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

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

Installation output

HTSeqGenie.Rcheck/00install.out

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


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

Tests output

HTSeqGenie.Rcheck/tests/doRUnit.Rout


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

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

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

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

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

Attaching package: 'BiocGenerics'

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

    IQR, mad, sd, var, xtabs

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

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

Loading required package: S4Vectors
Loading required package: stats4

Attaching package: 'S4Vectors'

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

    findMatches

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

    I, expand.grid, unname

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

Attaching package: 'Biostrings'

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

    strsplit

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

Attaching package: 'MatrixGenerics'

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

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

Loading required package: Biobase
Welcome to Bioconductor

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


Attaching package: 'Biobase'

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

    rowMedians

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

    anyMissing, rowMedians

Loading required package: VariantAnnotation

Attaching package: 'VariantAnnotation'

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

    tabulate

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


Executing test function test.alignReads  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:41:33.561942 INFO::preprocessReads.R/preprocessReads: starting...
2024-09-27 02:41:33.570888 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:41:33.574993 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-09-27 02:41:33.577064 DEBUG::tools.R/processChunks: starting...
2024-09-27 02:41:36.373407 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-09-27 02:41:36.374538 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/chunks/chunk_000001/logs/progress.log
2024-09-27 02:41:38.993243 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-09-27 02:41:38.9945 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/chunks/chunk_000002/logs/progress.log
2024-09-27 02:41:41.620219 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.044 minutes
2024-09-27 02:41:41.621585 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/chunks/chunk_000003/logs/progress.log
2024-09-27 02:41:44.231662 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-09-27 02:41:44.250451 DEBUG::tools.R/processChunks: done
2024-09-27 02:41:44.253478 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-09-27 02:41:44.255383 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/results/test_pe.adapter_contaminated_1.RData
2024-09-27 02:41:44.257796 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-09-27 02:41:44.259224 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/results/test_pe.adapter_contaminated_2.RData
2024-09-27 02:41:44.266301 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-09-27 02:41:44.268032 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/results/test_pe.summary_preprocess.tab
2024-09-27 02:41:44.270571 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/bams/processed.aligner_input_1.fastq ...
2024-09-27 02:41:44.27516 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/bams/processed.aligner_input_2.fastq ...
2024-09-27 02:41:44.278448 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/reports/shortReadReport_1 ...
2024-09-27 02:41:45.340011 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/reports/shortReadReport_2 ...
2024-09-27 02:41:46.089913 INFO::preprocessReads.R/preprocessReads: done
2024-09-27 02:41:46.161725 INFO::alignReads.R/alignReads: starting alignment...
2024-09-27 02:41:46.167402 DEBUG::tools.R/processChunks: starting...
2024-09-27 02:41:49.007085 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-09-27 02:41:49.008626 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/chunks/chunk_000001/logs/progress.log
2024-09-27 02:41:51.869812 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.048 minutes
2024-09-27 02:41:51.87164 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/chunks/chunk_000002/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-09-27 02:41:54.495843 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.044 minutes
2024-09-27 02:41:54.497489 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/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-09-27 02:41:57.087397 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-09-27 02:41:57.089812 DEBUG::tools.R/processChunks: done
2024-09-27 02:41:57.091095 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-09-27 02:41:57.272135 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-09-27 02:41:57.279943 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/results/test_pe.summary_alignment.tab
2024-09-27 02:41:57.286114 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/results/test_pe.summary_analyzed_bamstats.tab
2024-09-27 02:41:57.287535 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-09-27 02:41:57.492962 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.alignReads.b625358484d1b/results/test_pe.summary_target_lengths.tab
2024-09-27 02:41:57.528578 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-09-27 02:41:57.529282 INFO::alignReads.R/alignReads: done
 done successfully.



Executing test function test.alignReads.sparsechunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:41:57.769397 INFO::preprocessReads.R/preprocessReads: starting...
2024-09-27 02:41:57.772749 INFO::io.R/FastQStreamer.init: counting number of reads in file= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:41:57.832999 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 2 , totnbreads= 26 )
2024-09-27 02:41:57.837803 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:41:57.840742 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-09-27 02:41:57.84246 DEBUG::tools.R/processChunks: starting...
2024-09-27 02:42:00.684461 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-09-27 02:42:00.685611 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmptUhPsJ/test.alignReads.sparsechunks.b6253548cc2aa/chunks/chunk_000001/logs/progress.log
2024-09-27 02:42:03.279163 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.043 minutes
2024-09-27 02:42:03.280594 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmptUhPsJ/test.alignReads.sparsechunks.b6253548cc2aa/chunks/chunk_000002/logs/progress.log
2024-09-27 02:42:05.887658 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.043 minutes
2024-09-27 02:42:05.88925 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmptUhPsJ/test.alignReads.sparsechunks.b6253548cc2aa/chunks/chunk_000003/logs/progress.log
2024-09-27 02:42:08.545711 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.044 minutes
2024-09-27 02:42:08.547103 DEBUG::tools.R/processChunks: starting chunkid= 4 ; see logfile= /tmp/RtmptUhPsJ/test.alignReads.sparsechunks.b6253548cc2aa/chunks/chunk_000004/logs/progress.log
2024-09-27 02:42:11.111739 DEBUG::tools.R/processChunks: done with chunkid= 4 ; elapsed.time= 0.043 minutes
2024-09-27 02:42:11.133036 DEBUG::tools.R/processChunks: done
2024-09-27 02:42:11.135974 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-09-27 02:42:11.138025 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.alignReads.sparsechunks.b6253548cc2aa/results/test_pe.adapter_contaminated_1.RData
2024-09-27 02:42:11.14072 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-09-27 02:42:11.142239 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.alignReads.sparsechunks.b6253548cc2aa/results/test_pe.adapter_contaminated_2.RData
2024-09-27 02:42:11.150558 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-09-27 02:42:11.152327 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.alignReads.sparsechunks.b6253548cc2aa/results/test_pe.summary_preprocess.tab
2024-09-27 02:42:11.155134 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmptUhPsJ/test.alignReads.sparsechunks.b6253548cc2aa/bams/processed.aligner_input_1.fastq ...
2024-09-27 02:42:11.159598 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmptUhPsJ/test.alignReads.sparsechunks.b6253548cc2aa/bams/processed.aligner_input_2.fastq ...
2024-09-27 02:42:11.163719 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmptUhPsJ/test.alignReads.sparsechunks.b6253548cc2aa/reports/shortReadReport_1 ...
2024-09-27 02:42:12.203107 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmptUhPsJ/test.alignReads.sparsechunks.b6253548cc2aa/reports/shortReadReport_2 ...
2024-09-27 02:42:12.947016 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.alignReadsOneSingleEnd  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:42:13.100005 INFO::alignReads.R/alignReadsChunk: running gsnap...
2024-09-27 02:42:13.103729 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/RtmptUhPsJ/test.alignReadsOneSingleEnd.b6253db639c7/bams/test.alignReads /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq 2>&1
2024-09-27 02:42:13.314781 INFO::alignReads.R/createSummaryAlignment: counting unique bam reads...
2024-09-27 02:42:13.383311 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.alignReadsOneSingleEnd.b6253db639c7/results/test.alignReads.summary_alignment.tab
2024-09-27 02:42:13.42222 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.alignReadsOneSingleEnd.b6253db639c7/results/test.alignReads.summary_analyzed_bamstats.tab
2024-09-27 02:42:13.423486 INFO::alignReads.R/alignReadsChunk: done
 done successfully.



Executing test function test.annotateVariants  ... Timing stopped at: 0.001 0.002 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/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:42:13.635716 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.genotype.b62531d1f473f/results/test_pe.coverage.RData
2024-09-27 02:42:13.637173 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmptUhPsJ/test.genotype.b62531d1f473f/results/test_pe.coverage.bw
2024-09-27 02:42:13.72308 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.genotype.b62531d1f473f/results/test_pe.summary_coverage.tab
2024-09-27 02:42:13.724547 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-09-27 02:42:21.41621 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-09-27 02:42:21.479435 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-09-27 02:42:21.491761 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-09-27 02:42:21.492844 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.genotype.b62531d1f473f/results/test_pe.raw_variants.RData
2024-09-27 02:42:21.49479 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.genotype.b62531d1f473f/results/test_pe.filtered_variants.RData
2024-09-27 02:42:21.495942 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-09-27 02:42:21.496828 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-09-27 02:42:21.797693 INFO::analyzeVariants.R/writeVCF: ...done
2024-09-27 02:42:21.798613 INFO::analyzeVariants.R/.callGenotypes: calling genotypes...
2024-09-27 02:43:09.954651 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-09-27 02:43:10.258837 INFO::analyzeVariants.R/writeVCF: ...done
2024-09-27 02:43:10.259588 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/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:43:10.560174 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-09-27 02:43:18.329226 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-09-27 02:43:18.388757 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-09-27 02:43:18.401998 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-09-27 02:43:18.403133 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.wrap.callVariants.b6253163dece/results/test_pe.raw_variants.RData
2024-09-27 02:43:18.405093 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.wrap.callVariants.b6253163dece/results/test_pe.filtered_variants.RData
2024-09-27 02:43:18.406162 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.filters  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:43:18.510838 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-09-27 02:43:26.868645 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-09-27 02:43:26.913794 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-09-27 02:43:26.926461 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-09-27 02:43:26.927699 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.wrap.callVariants.filters.b6253554c3f5e/results/test_pe.raw_variants.RData
2024-09-27 02:43:26.929994 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.wrap.callVariants.filters.b6253554c3f5e/results/test_pe.filtered_variants.RData
2024-09-27 02:43:26.931036 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-09-27 02:43:26.932204 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-09-27 02:43:35.924036 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-09-27 02:43:35.953813 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-09-27 02:43:35.966572 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-09-27 02:43:35.967622 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.wrap.callVariants.filters.b6253554c3f5e/results/test_pe.raw_variants.RData
2024-09-27 02:43:35.96978 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.wrap.callVariants.filters.b6253554c3f5e/results/test_pe.filtered_variants.RData
2024-09-27 02:43:35.971456 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.which  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:43:36.204487 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-09-27 02:43:36.205827 INFO::analyzeVariants.R/buildTallyParam: restricting variant calls using 'which'
2024-09-27 02:43:39.475084 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-09-27 02:43:39.536796 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-09-27 02:43:39.550238 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-09-27 02:43:39.551378 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.wrap.callVariants.which.b62531a469cb2/results/test_pe.raw_variants.RData
2024-09-27 02:43:39.552893 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.wrap.callVariants.which.b62531a469cb2/results/test_pe.filtered_variants.RData
2024-09-27 02:43:39.55403 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.writeVCF.NULL  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:43:41.065156 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-09-27 02:43:41.065947 INFO::analyzeVariants.R/writeVCF: ...done
 done successfully.



Executing test function test.writeVCF.vcfStat  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:43:41.180216 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-09-27 02:43:41.316641 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-09-27 02:44:21.321659 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/jcdhqmbp/merged/results/bla.coverage.RData
2024-09-27 02:44:21.324893 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmptUhPsJ/jcdhqmbp/merged/results/bla.coverage.bw
2024-09-27 02:44:21.37119 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/jcdhqmbp/merged/results/bla.summary_coverage.tab
 done successfully.



Executing test function test.mergeCoverage.sparse  ... 2024-09-27 02:44:22.826869 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/rfcbhyvu/merged/results/bla.coverage.RData
2024-09-27 02:44:22.82841 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmptUhPsJ/rfcbhyvu/merged/results/bla.coverage.bw
2024-09-27 02:44:22.83763 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/rfcbhyvu/merged/results/bla.summary_coverage.tab
 done successfully.



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



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



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



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



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



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



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



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



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



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



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



Executing test function test.detectRRNA  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:44:24.829333 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-09-27 02:44:24.830131 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmptUhPsJ/test.detectRRNA.b62534d9d48d8/bams/rRNA_contam/input1.fastq
2024-09-27 02:44:24.832496 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/RtmptUhPsJ/test.detectRRNA.b62534d9d48d8/bams/rRNA_contam/test_se /tmp/RtmptUhPsJ/test.detectRRNA.b62534d9d48d8/bams/rRNA_contam/input1.fastq 2>&1
2024-09-27 02:44:24.974291 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-09-27 02:44:24.974991 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.detectRRNA.paired_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:44:25.05896 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-09-27 02:44:25.059632 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmptUhPsJ/test.detectRRNA.paired_end.b6253f1a7465/bams/rRNA_contam/input1.fastq
2024-09-27 02:44:25.060775 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmptUhPsJ/test.detectRRNA.paired_end.b6253f1a7465/bams/rRNA_contam/input2.fastq
2024-09-27 02:44:25.062413 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/RtmptUhPsJ/test.detectRRNA.paired_end.b6253f1a7465/bams/rRNA_contam/test_pe /tmp/RtmptUhPsJ/test.detectRRNA.paired_end.b6253f1a7465/bams/rRNA_contam/input1.fastq -a paired /tmp/RtmptUhPsJ/test.detectRRNA.paired_end.b6253f1a7465/bams/rRNA_contam/input2.fastq 2>&1
2024-09-27 02:44:25.289677 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-09-27 02:44:25.290462 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.getRRNAIds  ... 2024-09-27 02:44:25.305081 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/RtmptUhPsJ/test_get_rRNA_idscxypalzm/test_pe /tmp/RtmptUhPsJ/test_get_rRNA_idscxypalzm/1.fastq -a paired /tmp/RtmptUhPsJ/test_get_rRNA_idscxypalzm/2.fastq 2>&1
 done successfully.



Executing test function test.getRRNAIds_random  ... 2024-09-27 02:44:25.774891 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/RtmptUhPsJ/test_get_rRNAIds_randomhjcrbeaw/test_pe /tmp/RtmptUhPsJ/test_get_rRNAIds_randomhjcrbeaw/1.fastq 2>&1
 done successfully.



Executing test function test.filterByLength  ... 2024-09-27 02:44:26.029156 INFO::filterQuality.R/filterQuality: filterByLength...
2024-09-27 02:44:26.030433 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 0.5
2024-09-27 02:44:26.031093 INFO::filterQuality.R/filterByLength: done
2024-09-27 02:44:26.063431 INFO::filterQuality.R/filterQuality: filterByLength...
2024-09-27 02:44:26.064065 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 1
2024-09-27 02:44:26.064684 INFO::filterQuality.R/filterByLength: done
 done successfully.



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



Executing test function test.trimTailsByQuality  ... 2024-09-27 02:44:26.100199 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-09-27 02:44:26.106522 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-09-27 02:44:26.107255 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-09-27 02:44:26.110459 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-09-27 02:44:26.111166 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-09-27 02:44:26.114287 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-09-27 02:44:26.115024 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-09-27 02:44:26.11819 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/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:44:26.308088 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:44:26.309648 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



Executing test function test.FastQStreamer.getReads.pefq.subsample  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:44:26.416496 INFO::io.R/FastQStreamer.init: counting number of reads in file= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:44:26.469119 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-09-27 02:44:26.471028 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:44:26.472587 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



Executing test function test.FastQStreamer.getReads.segz  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:44:26.61237 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/reads.fastq.gz
 done successfully.



Executing test function test.FastQStreamer.getReads.truncated  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:44:26.715346 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/truncated.fastq.gz
 done successfully.



Executing test function test.FastQStreamer.subsampler.isdeterministic  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:44:26.829239 INFO::io.R/FastQStreamer.init: counting number of reads in file= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:44:26.859652 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-09-27 02:44:26.86136 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:44:26.862933 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:44:26.987908 INFO::io.R/FastQStreamer.init: counting number of reads in file= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:44:27.019325 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-09-27 02:44:27.02108 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:44:27.022621 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



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



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



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



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



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



Executing test function test.mergeLanes  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:44:27.535307 INFO::preprocessReads.R/preprocessReads: starting...
2024-09-27 02:44:27.542253 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:44:27.545701 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-09-27 02:44:27.548071 DEBUG::tools.R/processChunks: starting...
2024-09-27 02:44:31.068511 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-09-27 02:44:31.069787 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/chunks/chunk_000001/logs/progress.log
2024-09-27 02:44:33.576435 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.042 minutes
2024-09-27 02:44:33.577914 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/chunks/chunk_000002/logs/progress.log
2024-09-27 02:44:36.06961 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.041 minutes
2024-09-27 02:44:36.071178 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/chunks/chunk_000003/logs/progress.log
2024-09-27 02:44:38.605669 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.042 minutes
2024-09-27 02:44:38.645226 DEBUG::tools.R/processChunks: done
2024-09-27 02:44:38.647649 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-09-27 02:44:38.648967 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.adapter_contaminated_1.RData
2024-09-27 02:44:38.650605 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-09-27 02:44:38.651801 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.adapter_contaminated_2.RData
2024-09-27 02:44:38.658345 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-09-27 02:44:38.65987 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.summary_preprocess.tab
2024-09-27 02:44:38.662078 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/bams/processed.aligner_input_1.fastq ...
2024-09-27 02:44:38.666234 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/bams/processed.aligner_input_2.fastq ...
2024-09-27 02:44:38.669494 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/reports/shortReadReport_1 ...
2024-09-27 02:44:39.740799 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/reports/shortReadReport_2 ...
2024-09-27 02:44:40.512606 INFO::preprocessReads.R/preprocessReads: done
2024-09-27 02:44:40.901655 INFO::alignReads.R/alignReads: starting alignment...
2024-09-27 02:44:40.906747 DEBUG::tools.R/processChunks: starting...
2024-09-27 02:44:43.847729 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-09-27 02:44:43.849349 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/chunks/chunk_000001/logs/progress.log
2024-09-27 02:44:46.38028 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.042 minutes
2024-09-27 02:44:46.381917 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/chunks/chunk_000002/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-09-27 02:44:48.934979 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.043 minutes
2024-09-27 02:44:48.936691 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/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-09-27 02:44:51.520073 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-09-27 02:44:51.522756 DEBUG::tools.R/processChunks: done
2024-09-27 02:44:51.524484 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-09-27 02:44:52.145338 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-09-27 02:44:52.152088 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.summary_alignment.tab
2024-09-27 02:44:52.161543 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.summary_analyzed_bamstats.tab
2024-09-27 02:44:52.162984 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-09-27 02:44:52.3538 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.summary_target_lengths.tab
2024-09-27 02:44:52.388785 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-09-27 02:44:52.389508 INFO::alignReads.R/alignReads: done
2024-09-27 02:44:52.492989 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-09-27 02:44:52.514191 DEBUG::tools.R/processChunks: starting...
2024-09-27 02:44:55.707384 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-09-27 02:44:55.709152 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/chunks/chunk_000001/logs/progress.log
2024-09-27 02:44:58.088508 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.04 minutes
2024-09-27 02:44:58.090046 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/chunks/chunk_000002/logs/progress.log
2024-09-27 02:45:00.45228 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.039 minutes
2024-09-27 02:45:00.454003 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/chunks/chunk_000003/logs/progress.log
2024-09-27 02:45:03.265758 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.047 minutes
2024-09-27 02:45:03.268067 DEBUG::tools.R/processChunks: done
2024-09-27 02:45:03.26951 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-09-27 02:45:03.280288 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.counts_exon.tab
2024-09-27 02:45:03.287901 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.counts_exon_disjoint.tab
2024-09-27 02:45:03.293058 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.counts_gene.tab
2024-09-27 02:45:03.297158 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.counts_gene_coding.tab
2024-09-27 02:45:03.301206 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.counts_gene_exonic.tab
2024-09-27 02:45:03.305524 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.counts_intergenic.tab
2024-09-27 02:45:03.31249 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.counts_intron.tab
2024-09-27 02:45:03.314395 INFO::countGenomicFeatures.R/mergeCounts: done
2024-09-27 02:45:03.319007 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.summary_counts.tab
2024-09-27 02:45:03.320323 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-09-27 02:45:03.55592 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-09-27 02:45:03.556589 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-09-27 02:45:03.657357 INFO::coverage.R/calculateCoverage: starting...
2024-09-27 02:45:03.662069 DEBUG::tools.R/processChunks: starting...
2024-09-27 02:45:06.919078 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-09-27 02:45:06.920838 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/chunks/chunk_000001/logs/progress.log
2024-09-27 02:45:09.090011 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.036 minutes
2024-09-27 02:45:09.091636 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/chunks/chunk_000002/logs/progress.log
2024-09-27 02:45:11.266911 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.036 minutes
2024-09-27 02:45:11.268544 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/chunks/chunk_000003/logs/progress.log
2024-09-27 02:45:13.438742 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.036 minutes
2024-09-27 02:45:13.441307 DEBUG::tools.R/processChunks: done
2024-09-27 02:45:14.877117 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.coverage.RData
2024-09-27 02:45:14.878501 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.coverage.bw
2024-09-27 02:45:14.889071 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.summary_coverage.tab
2024-09-27 02:45:14.890103 INFO::coverage.R/calculateCoverage: done
2024-09-27 02:45:14.891994 INFO::analyzeVariants/analyzeVariants: starting ...
2024-09-27 02:45:14.984222 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-09-27 02:45:18.132726 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-09-27 02:45:18.190181 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-09-27 02:45:18.202663 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-09-27 02:45:18.203717 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.raw_variants.RData
2024-09-27 02:45:18.205064 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.filtered_variants.RData
2024-09-27 02:45:18.206093 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-09-27 02:45:18.206896 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-09-27 02:45:18.375505 INFO::analyzeVariants.R/writeVCF: ...done
2024-09-27 02:45:18.454457 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/results/test_pe.summary_variants.tab
2024-09-27 02:45:18.456364 INFO::analyzeVariants/analyzeVariants: done
2024-09-27 02:45:18.459868 INFO::Pipeline run successful.
2024-09-27 02:45:18.830794 INFO::mergeLanes.R/doMergeLanes: starting...
2024-09-27 02:45:18.83642 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-09-27 02:45:18.838546 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.adapter_contaminated_1.RData
2024-09-27 02:45:18.841158 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-09-27 02:45:18.842964 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.adapter_contaminated_2.RData
2024-09-27 02:45:18.85376 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-09-27 02:45:18.855814 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.summary_preprocess.tab
2024-09-27 02:45:18.857815 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-09-27 02:45:19.068383 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-09-27 02:45:19.075057 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.summary_alignment.tab
2024-09-27 02:45:19.082292 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.summary_analyzed_bamstats.tab
2024-09-27 02:45:19.084189 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-09-27 02:45:19.297143 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.summary_target_lengths.tab
2024-09-27 02:45:19.338157 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-09-27 02:45:19.395526 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-09-27 02:45:19.415467 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.counts_exon.tab
2024-09-27 02:45:19.425318 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.counts_exon_disjoint.tab
2024-09-27 02:45:19.43109 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.counts_gene.tab
2024-09-27 02:45:19.436073 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.counts_gene_coding.tab
2024-09-27 02:45:19.440916 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.counts_gene_exonic.tab
2024-09-27 02:45:19.446658 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.counts_intergenic.tab
2024-09-27 02:45:19.456869 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.counts_intron.tab
2024-09-27 02:45:19.458997 INFO::countGenomicFeatures.R/mergeCounts: done
2024-09-27 02:45:19.465163 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.summary_counts.tab
2024-09-27 02:45:19.466693 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-09-27 02:45:19.652494 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-09-27 02:45:21.689202 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.coverage.RData
2024-09-27 02:45:21.692149 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.coverage.bw
2024-09-27 02:45:21.702769 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.summary_coverage.tab
2024-09-27 02:45:21.752433 INFO::analyzeVariants/analyzeVariants: starting ...
2024-09-27 02:45:21.857113 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-09-27 02:45:25.137837 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-09-27 02:45:25.197191 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-09-27 02:45:25.210591 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-09-27 02:45:25.211762 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.raw_variants.RData
2024-09-27 02:45:25.213187 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.filtered_variants.RData
2024-09-27 02:45:25.214259 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-09-27 02:45:25.215089 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-09-27 02:45:25.395434 INFO::analyzeVariants.R/writeVCF: ...done
2024-09-27 02:45:25.481016 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.mergeLanes.b62534a1f618b/merged/results/merged.summary_variants.tab
2024-09-27 02:45:25.4832 INFO::analyzeVariants/analyzeVariants: done
2024-09-27 02:45:25.489371 INFO::mergeLanes.R/doMergeLanes: merge lanes successful.
 done successfully.



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



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



Executing test function test.preprocessReads  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:45:26.180358 INFO::preprocessReads.R/preprocessReads: starting...
2024-09-27 02:45:26.193507 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:45:26.200829 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-09-27 02:45:26.207106 DEBUG::tools.R/processChunks: starting...
2024-09-27 02:45:29.215229 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-09-27 02:45:29.216399 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmptUhPsJ/test.preprocessReads.b62535c7d8241/chunks/chunk_000001/logs/progress.log
2024-09-27 02:45:31.77872 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.043 minutes
2024-09-27 02:45:31.811125 DEBUG::tools.R/processChunks: done
2024-09-27 02:45:31.813045 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-09-27 02:45:31.814222 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.preprocessReads.b62535c7d8241/results/test_pe.adapter_contaminated_1.RData
2024-09-27 02:45:31.815561 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-09-27 02:45:31.816608 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.preprocessReads.b62535c7d8241/results/test_pe.adapter_contaminated_2.RData
2024-09-27 02:45:31.82165 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-09-27 02:45:31.822966 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.preprocessReads.b62535c7d8241/results/test_pe.summary_preprocess.tab
2024-09-27 02:45:31.824691 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmptUhPsJ/test.preprocessReads.b62535c7d8241/bams/processed.aligner_input_1.fastq ...
2024-09-27 02:45:31.829204 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmptUhPsJ/test.preprocessReads.b62535c7d8241/bams/processed.aligner_input_2.fastq ...
2024-09-27 02:45:31.832958 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmptUhPsJ/test.preprocessReads.b62535c7d8241/reports/shortReadReport_1 ...
2024-09-27 02:45:33.070069 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmptUhPsJ/test.preprocessReads.b62535c7d8241/reports/shortReadReport_2 ...
2024-09-27 02:45:33.813172 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads.minichunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:45:34.056793 INFO::preprocessReads.R/preprocessReads: starting...
2024-09-27 02:45:34.062882 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:45:34.065919 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-09-27 02:45:34.068038 DEBUG::tools.R/processChunks: starting...
2024-09-27 02:45:37.225946 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-09-27 02:45:37.227172 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmptUhPsJ/test.preprocessReads.minichunks.b6253468bdb8c/chunks/chunk_000001/logs/progress.log
2024-09-27 02:45:40.092401 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.048 minutes
2024-09-27 02:45:40.093902 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmptUhPsJ/test.preprocessReads.minichunks.b6253468bdb8c/chunks/chunk_000002/logs/progress.log
2024-09-27 02:45:42.594468 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.042 minutes
2024-09-27 02:45:42.595822 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmptUhPsJ/test.preprocessReads.minichunks.b6253468bdb8c/chunks/chunk_000003/logs/progress.log
2024-09-27 02:45:45.141791 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.042 minutes
2024-09-27 02:45:45.176597 DEBUG::tools.R/processChunks: done
2024-09-27 02:45:45.179107 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-09-27 02:45:45.180484 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.preprocessReads.minichunks.b6253468bdb8c/results/test_pe.adapter_contaminated_1.RData
2024-09-27 02:45:45.182179 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-09-27 02:45:45.183398 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.preprocessReads.minichunks.b6253468bdb8c/results/test_pe.adapter_contaminated_2.RData
2024-09-27 02:45:45.190347 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-09-27 02:45:45.191904 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.preprocessReads.minichunks.b6253468bdb8c/results/test_pe.summary_preprocess.tab
2024-09-27 02:45:45.194209 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmptUhPsJ/test.preprocessReads.minichunks.b6253468bdb8c/bams/processed.aligner_input_1.fastq ...
2024-09-27 02:45:45.1982 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmptUhPsJ/test.preprocessReads.minichunks.b6253468bdb8c/bams/processed.aligner_input_2.fastq ...
2024-09-27 02:45:45.202034 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmptUhPsJ/test.preprocessReads.minichunks.b6253468bdb8c/reports/shortReadReport_1 ...
2024-09-27 02:45:46.272686 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmptUhPsJ/test.preprocessReads.minichunks.b6253468bdb8c/reports/shortReadReport_2 ...
2024-09-27 02:45:47.027103 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads_single_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmptUhPsJ/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:45:47.639997 INFO::preprocessReads.R/preprocessReads: starting...
2024-09-27 02:45:47.660618 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-09-27 02:45:47.664069 DEBUG::tools.R/processChunks: starting...
2024-09-27 02:45:50.652884 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-09-27 02:45:50.654117 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmptUhPsJ/test.preprocessReads_single_end.b625335ce437b/chunks/chunk_000001/logs/progress.log
2024-09-27 02:45:53.130762 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.041 minutes
2024-09-27 02:45:53.158771 DEBUG::tools.R/processChunks: done
2024-09-27 02:45:53.161049 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-09-27 02:45:53.16261 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.preprocessReads_single_end.b625335ce437b/results/test_se.adapter_contaminated_1.RData
2024-09-27 02:45:53.167764 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-09-27 02:45:53.169033 INFO::io.R/saveWithID: saving file= /tmp/RtmptUhPsJ/test.preprocessReads_single_end.b625335ce437b/results/test_se.summary_preprocess.tab
2024-09-27 02:45:53.170435 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmptUhPsJ/test.preprocessReads_single_end.b625335ce437b/bams/processed.aligner_input_1.fastq ...
2024-09-27 02:45:53.17421 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmptUhPsJ/test.preprocessReads_single_end.b625335ce437b/reports/shortReadReport_1 ...
2024-09-27 02:45:54.221122 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= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-09-27 02:45:55.079136 INFO::preprocessReads.R/preprocessReads: starting...
2024-09-27 02:45:55.10174 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_1.fastq.gz
2024-09-27 02:45:55.107181 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /media/volume/teran2_disk/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_2.fastq.gz
2024-09-27 02:45:55.109455 DEBUG::tools.R/processChunks: starting...
2024-09-27 02:45:58.436125 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-09-27 02:45:58.43729 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-09-27 02:46:01.127405 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.045 minutes
2024-09-27 02:46:01.158571 DEBUG::tools.R/processChunks: done
2024-09-27 02:46:01.160551 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-09-27 02:46:01.161678 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_1.RData
2024-09-27 02:46:01.163001 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-09-27 02:46:01.164011 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_2.RData
2024-09-27 02:46:01.168957 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-09-27 02:46:01.170255 INFO::io.R/saveWithID: saving file= test/results/test.summary_preprocess.tab
2024-09-27 02:46:01.171917 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_1.fastq ...
2024-09-27 02:46:01.17688 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_2.fastq ...
2024-09-27 02:46:01.181899 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_1 ...
2024-09-27 02:46:55.034085 DEBUG::tools.R/traceMem: wired.mem=-28.793516 GiB
2024-09-27 02:47:55.101182 DEBUG::tools.R/traceMem: wired.mem=-32.399651 GiB
2024-09-27 02:48:55.172479 DEBUG::tools.R/traceMem: wired.mem=-11.819692 GiB
2024-09-27 02:49:55.239469 DEBUG::tools.R/traceMem: wired.mem=-34.496655 GiB
2024-09-27 02:50:55.305216 DEBUG::tools.R/traceMem: wired.mem=-36.962963 GiB
2024-09-27 02:51:55.370836 DEBUG::tools.R/traceMem: wired.mem=-31.014474 GiB
2024-09-27 02:52:55.437515 DEBUG::tools.R/traceMem: wired.mem=-28.578746 GiB
2024-09-27 02:53:55.50317 DEBUG::tools.R/traceMem: wired.mem=-28.039631 GiB
2024-09-27 02:54:55.570137 DEBUG::tools.R/traceMem: wired.mem=-29.079794 GiB
2024-09-27 02:55:55.638055 DEBUG::tools.R/traceMem: wired.mem=-30.099722 GiB
2024-09-27 02:56:55.70526 DEBUG::tools.R/traceMem: wired.mem=-29.790564 GiB
2024-09-27 02:57:55.771441 DEBUG::tools.R/traceMem: wired.mem=-24.162111 GiB
2024-09-27 02:58:55.837599 DEBUG::tools.R/traceMem: wired.mem=-27.748069 GiB
2024-09-27 02:59:55.903028 DEBUG::tools.R/traceMem: wired.mem=-25.428988 GiB
2024-09-27 03:00:55.970539 DEBUG::tools.R/traceMem: wired.mem=-25.815110 GiB
2024-09-27 03:01:56.251237 DEBUG::tools.R/traceMem: wired.mem=-27.274686 GiB
2024-09-27 03:02:56.317497 DEBUG::tools.R/traceMem: wired.mem=-24.642974 GiB
2024-09-27 03:03:56.384989 DEBUG::tools.R/traceMem: wired.mem=-31.140770 GiB
2024-09-27 03:04:56.453138 DEBUG::tools.R/traceMem: wired.mem=-30.012772 GiB
2024-09-27 03:05:56.521729 DEBUG::tools.R/traceMem: wired.mem=-28.116586 GiB
2024-09-27 03:06:56.586901 DEBUG::tools.R/traceMem: wired.mem=-20.295496 GiB
2024-09-27 03:07:56.654317 DEBUG::tools.R/traceMem: wired.mem=-23.194857 GiB
2024-09-27 03:08:56.718676 DEBUG::tools.R/traceMem: wired.mem=-31.947125 GiB
2024-09-27 03:09:56.784259 DEBUG::tools.R/traceMem: wired.mem=-34.901160 GiB
2024-09-27 03:10:56.851139 DEBUG::tools.R/traceMem: wired.mem=-33.553068 GiB
2024-09-27 03:11:56.917805 DEBUG::tools.R/traceMem: wired.mem=-35.593441 GiB
2024-09-27 03:12:56.983208 DEBUG::tools.R/traceMem: wired.mem=-36.441125 GiB
2024-09-27 03:13:57.050444 DEBUG::tools.R/traceMem: wired.mem=-32.809890 GiB
2024-09-27 03:14:57.106765 DEBUG::tools.R/traceMem: wired.mem=-31.590781 GiB
2024-09-27 03:15:57.176396 DEBUG::tools.R/traceMem: wired.mem=-33.984909 GiB

Example timings

HTSeqGenie.Rcheck/HTSeqGenie-Ex.timings

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