##############################################################################
##############################################################################
###
### Running command:
###
###   /home/biocbuild/R/R/bin/R CMD check --install=check:HTSeqGenie.install-out.txt --library=/home/biocbuild/R/R/site-library --no-vignettes --timings HTSeqGenie_4.36.0.tar.gz
###
##############################################################################
##############################################################################


* using log directory ‘/home/biocbuild/bbs-3.20-bioc/meat/HTSeqGenie.Rcheck’
* using R version 4.4.1 (2024-06-14)
* using platform: aarch64-unknown-linux-gnu
* R was compiled by
    gcc (GCC) 12.2.1 20220819 (openEuler 12.2.1-14)
    GNU Fortran (GCC) 10.3.1
* running under: openEuler 22.03 (LTS-SP1)
* using session charset: UTF-8
* using option ‘--no-vignettes’
* checking for file ‘HTSeqGenie/DESCRIPTION’ ... OK
* checking extension type ... Package
* this is package ‘HTSeqGenie’ version ‘4.36.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 running R code from vignettes ... SKIPPED
* checking re-building of vignette outputs ... SKIPPED
* checking PDF version of manual ... OK
* DONE

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

##############################################################################
##############################################################################
###
### Running command:
###
###   /home/biocbuild/R/R/bin/R CMD INSTALL HTSeqGenie
###
##############################################################################
##############################################################################


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

R version 4.4.1 (2024-06-14) -- "Race for Your Life"
Copyright (C) 2024 The R Foundation for Statistical Computing
Platform: aarch64-unknown-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, saveRDS, 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= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:00:34.813763 INFO::preprocessReads.R/preprocessReads: starting...
2024-11-20 09:00:34.823334 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:00:34.828767 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-11-20 09:00:34.831486 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:00:38.156013 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:00:38.157941 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/chunks/chunk_000001/logs/progress.log
2024-11-20 09:00:41.043513 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.048 minutes
2024-11-20 09:00:41.045315 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/chunks/chunk_000002/logs/progress.log
2024-11-20 09:00:43.894215 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.047 minutes
2024-11-20 09:00:43.896039 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/chunks/chunk_000003/logs/progress.log
2024-11-20 09:00:46.771804 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.048 minutes
2024-11-20 09:00:46.810748 DEBUG::tools.R/processChunks: done
2024-11-20 09:00:46.815607 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-11-20 09:00:46.818686 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/results/test_pe.adapter_contaminated_1.RData
2024-11-20 09:00:46.822386 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-11-20 09:00:46.824924 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/results/test_pe.adapter_contaminated_2.RData
2024-11-20 09:00:46.837302 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-11-20 09:00:46.840477 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/results/test_pe.summary_preprocess.tab
2024-11-20 09:00:46.845151 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/bams/processed.aligner_input_1.fastq ...
2024-11-20 09:00:46.852403 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/bams/processed.aligner_input_2.fastq ...
2024-11-20 09:00:46.858561 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/reports/shortReadReport_1 ...
2024-11-20 09:00:48.793634 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/reports/shortReadReport_2 ...
2024-11-20 09:00:50.349607 INFO::preprocessReads.R/preprocessReads: done
2024-11-20 09:00:50.408889 INFO::alignReads.R/alignReads: starting alignment...
2024-11-20 09:00:50.415922 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:00:53.921967 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:00:53.92423 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/chunks/chunk_000001/logs/progress.log
2024-11-20 09:00:57.109842 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.053 minutes
2024-11-20 09:00:57.112277 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/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-11-20 09:00:59.839007 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.045 minutes
2024-11-20 09:00:59.841331 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/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-11-20 09:01:02.609798 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.046 minutes
2024-11-20 09:01:02.613211 DEBUG::tools.R/processChunks: done
2024-11-20 09:01:02.61524 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-11-20 09:01:02.985279 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-11-20 09:01:02.997303 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/results/test_pe.summary_alignment.tab
2024-11-20 09:01:03.008426 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/results/test_pe.summary_analyzed_bamstats.tab
2024-11-20 09:01:03.011005 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-11-20 09:01:03.303113 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.d8edf1a6fbdea/results/test_pe.summary_target_lengths.tab
2024-11-20 09:01:03.366213 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-11-20 09:01:03.367681 INFO::alignReads.R/alignReads: done
 done successfully.



Executing test function test.alignReads.sparsechunks  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:01:03.666318 INFO::preprocessReads.R/preprocessReads: starting...
2024-11-20 09:01:03.669906 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:01:03.749747 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 2 , totnbreads= 26 )
2024-11-20 09:01:03.756286 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:01:03.760739 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-11-20 09:01:03.763435 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:01:07.062455 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:01:07.064456 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.sparsechunks.d8edf1dd7fce8/chunks/chunk_000001/logs/progress.log
2024-11-20 09:01:09.927618 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.048 minutes
2024-11-20 09:01:09.929717 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.sparsechunks.d8edf1dd7fce8/chunks/chunk_000002/logs/progress.log
2024-11-20 09:01:12.731266 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.047 minutes
2024-11-20 09:01:12.733276 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.sparsechunks.d8edf1dd7fce8/chunks/chunk_000003/logs/progress.log
2024-11-20 09:01:15.658742 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.049 minutes
2024-11-20 09:01:15.66063 DEBUG::tools.R/processChunks: starting chunkid= 4 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.sparsechunks.d8edf1dd7fce8/chunks/chunk_000004/logs/progress.log
2024-11-20 09:01:18.482334 DEBUG::tools.R/processChunks: done with chunkid= 4 ; elapsed.time= 0.047 minutes
2024-11-20 09:01:18.52554 DEBUG::tools.R/processChunks: done
2024-11-20 09:01:18.530794 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-11-20 09:01:18.534281 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.sparsechunks.d8edf1dd7fce8/results/test_pe.adapter_contaminated_1.RData
2024-11-20 09:01:18.538564 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-11-20 09:01:18.541268 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.sparsechunks.d8edf1dd7fce8/results/test_pe.adapter_contaminated_2.RData
2024-11-20 09:01:18.556194 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-11-20 09:01:18.559467 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.sparsechunks.d8edf1dd7fce8/results/test_pe.summary_preprocess.tab
2024-11-20 09:01:18.564623 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.sparsechunks.d8edf1dd7fce8/bams/processed.aligner_input_1.fastq ...
2024-11-20 09:01:18.572135 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.sparsechunks.d8edf1dd7fce8/bams/processed.aligner_input_2.fastq ...
2024-11-20 09:01:18.577842 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.sparsechunks.d8edf1dd7fce8/reports/shortReadReport_1 ...
2024-11-20 09:01:20.49382 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReads.sparsechunks.d8edf1dd7fce8/reports/shortReadReport_2 ...
2024-11-20 09:01:22.036849 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.alignReadsOneSingleEnd  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:01:22.250616 INFO::alignReads.R/alignReadsChunk: running gsnap...
2024-11-20 09:01:22.257415 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 /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReadsOneSingleEnd.d8edf7b42e919/bams/test.alignReads /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq 2>&1
2024-11-20 09:01:22.403151 INFO::alignReads.R/createSummaryAlignment: counting unique bam reads...
2024-11-20 09:01:22.532607 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReadsOneSingleEnd.d8edf7b42e919/results/test.alignReads.summary_alignment.tab
2024-11-20 09:01:22.579029 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.alignReadsOneSingleEnd.d8edf7b42e919/results/test.alignReads.summary_analyzed_bamstats.tab
2024-11-20 09:01:22.581058 INFO::alignReads.R/alignReadsChunk: done
 done successfully.



Executing test function test.annotateVariants  ... Timing stopped at: 0.001 0.002 0.004
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= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:01:22.975388 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.genotype.d8edf837a7ad/results/test_pe.coverage.RData
2024-11-20 09:01:22.977703 INFO::coverage.R/saveCoverage: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.genotype.d8edf837a7ad/results/test_pe.coverage.bw
2024-11-20 09:01:23.171716 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.genotype.d8edf837a7ad/results/test_pe.summary_coverage.tab
2024-11-20 09:01:23.174014 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-11-20 09:01:36.274247 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-11-20 09:01:36.412714 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-11-20 09:01:36.44208 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-11-20 09:01:36.444366 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.genotype.d8edf837a7ad/results/test_pe.raw_variants.RData
2024-11-20 09:01:36.448084 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.genotype.d8edf837a7ad/results/test_pe.filtered_variants.RData
2024-11-20 09:01:36.450237 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-11-20 09:01:36.45215 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-11-20 09:01:37.074186 INFO::analyzeVariants.R/writeVCF: ...done
2024-11-20 09:01:37.076074 INFO::analyzeVariants.R/.callGenotypes: calling genotypes...
2024-11-20 09:03:02.938771 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-11-20 09:03:03.600165 INFO::analyzeVariants.R/writeVCF: ...done
2024-11-20 09:03:03.601597 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= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:03:04.246491 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-11-20 09:03:17.330091 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-11-20 09:03:17.448077 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-11-20 09:03:17.473619 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-11-20 09:03:17.475542 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.wrap.callVariants.d8edf5c438bfc/results/test_pe.raw_variants.RData
2024-11-20 09:03:17.478624 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.wrap.callVariants.d8edf5c438bfc/results/test_pe.filtered_variants.RData
2024-11-20 09:03:17.480702 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.filters  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:03:19.522001 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-11-20 09:03:32.761561 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-11-20 09:03:32.852636 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-11-20 09:03:32.883972 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-11-20 09:03:32.886319 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.wrap.callVariants.filters.d8edf3dbf3b8a/results/test_pe.raw_variants.RData
2024-11-20 09:03:32.889974 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.wrap.callVariants.filters.d8edf3dbf3b8a/results/test_pe.filtered_variants.RData
2024-11-20 09:03:32.892135 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-11-20 09:03:32.894406 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-11-20 09:03:46.472096 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-11-20 09:03:46.529478 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-11-20 09:03:46.554477 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-11-20 09:03:46.556446 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.wrap.callVariants.filters.d8edf3dbf3b8a/results/test_pe.raw_variants.RData
2024-11-20 09:03:46.559665 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.wrap.callVariants.filters.d8edf3dbf3b8a/results/test_pe.filtered_variants.RData
2024-11-20 09:03:46.562152 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.which  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:03:46.849159 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-11-20 09:03:46.851116 INFO::analyzeVariants.R/buildTallyParam: restricting variant calls using 'which'
2024-11-20 09:03:50.556593 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-11-20 09:03:50.665196 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-11-20 09:03:50.689053 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-11-20 09:03:50.690902 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.wrap.callVariants.which.d8edfb273143/results/test_pe.raw_variants.RData
2024-11-20 09:03:50.693188 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.wrap.callVariants.which.d8edfb273143/results/test_pe.filtered_variants.RData
2024-11-20 09:03:50.694923 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.writeVCF.NULL  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:03:50.863022 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-11-20 09:03:50.864742 INFO::analyzeVariants.R/writeVCF: ...done
 done successfully.



Executing test function test.writeVCF.vcfStat  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:03:51.105996 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-11-20 09:03:51.41456 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-11-20 09:05:04.838351 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/rvxpglfy/merged/results/bla.coverage.RData
2024-11-20 09:05:04.841362 INFO::coverage.R/saveCoverage: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/rvxpglfy/merged/results/bla.coverage.bw
2024-11-20 09:05:04.955896 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/rvxpglfy/merged/results/bla.summary_coverage.tab
 done successfully.



Executing test function test.mergeCoverage.sparse  ... 2024-11-20 09:05:06.399702 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/ktxvobwf/merged/results/bla.coverage.RData
2024-11-20 09:05:06.401713 INFO::coverage.R/saveCoverage: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/ktxvobwf/merged/results/bla.coverage.bw
2024-11-20 09:05:06.41634 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/ktxvobwf/merged/results/bla.summary_coverage.tab
 done successfully.



Executing test function test.checkConfig.analyzeVariants  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/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= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
 done successfully.



Executing test function test.checkConfig.alignReads  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/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= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:05:08.153326 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-11-20 09:05:08.154849 INFO::io.R/writeFastQFiles: writing filename= /home/biocbuild/tmp/Rtmp2ZcOnT/test.detectRRNA.d8edf646bcfa/bams/rRNA_contam/input1.fastq
2024-11-20 09:05:08.159581 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 /home/biocbuild/tmp/Rtmp2ZcOnT/test.detectRRNA.d8edf646bcfa/bams/rRNA_contam/test_se /home/biocbuild/tmp/Rtmp2ZcOnT/test.detectRRNA.d8edf646bcfa/bams/rRNA_contam/input1.fastq 2>&1
2024-11-20 09:05:08.272511 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-11-20 09:05:08.273899 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.detectRRNA.paired_end  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:05:08.479597 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-11-20 09:05:08.481007 INFO::io.R/writeFastQFiles: writing filename= /home/biocbuild/tmp/Rtmp2ZcOnT/test.detectRRNA.paired_end.d8edf3fc6ffa9/bams/rRNA_contam/input1.fastq
2024-11-20 09:05:08.483199 INFO::io.R/writeFastQFiles: writing filename= /home/biocbuild/tmp/Rtmp2ZcOnT/test.detectRRNA.paired_end.d8edf3fc6ffa9/bams/rRNA_contam/input2.fastq
2024-11-20 09:05:08.486412 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 /home/biocbuild/tmp/Rtmp2ZcOnT/test.detectRRNA.paired_end.d8edf3fc6ffa9/bams/rRNA_contam/test_pe /home/biocbuild/tmp/Rtmp2ZcOnT/test.detectRRNA.paired_end.d8edf3fc6ffa9/bams/rRNA_contam/input1.fastq -a paired /home/biocbuild/tmp/Rtmp2ZcOnT/test.detectRRNA.paired_end.d8edf3fc6ffa9/bams/rRNA_contam/input2.fastq 2>&1
2024-11-20 09:05:08.766663 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-11-20 09:05:08.768139 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.getRRNAIds  ... 2024-11-20 09:05:08.796568 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 /home/biocbuild/tmp/Rtmp2ZcOnT/test_get_rRNA_idsksrbhyag/test_pe /home/biocbuild/tmp/Rtmp2ZcOnT/test_get_rRNA_idsksrbhyag/1.fastq -a paired /home/biocbuild/tmp/Rtmp2ZcOnT/test_get_rRNA_idsksrbhyag/2.fastq 2>&1
 done successfully.



Executing test function test.getRRNAIds_random  ... 2024-11-20 09:05:09.078827 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 /home/biocbuild/tmp/Rtmp2ZcOnT/test_get_rRNAIds_randomncpoaeik/test_pe /home/biocbuild/tmp/Rtmp2ZcOnT/test_get_rRNAIds_randomncpoaeik/1.fastq 2>&1
 done successfully.



Executing test function test.filterByLength  ... 2024-11-20 09:05:09.250514 INFO::filterQuality.R/filterQuality: filterByLength...
2024-11-20 09:05:09.252491 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 0.5
2024-11-20 09:05:09.253716 INFO::filterQuality.R/filterByLength: done
2024-11-20 09:05:09.320006 INFO::filterQuality.R/filterQuality: filterByLength...
2024-11-20 09:05:09.321232 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 1
2024-11-20 09:05:09.322425 INFO::filterQuality.R/filterByLength: done
 done successfully.



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



Executing test function test.trimTailsByQuality  ... 2024-11-20 09:05:09.395722 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-11-20 09:05:09.408479 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-11-20 09:05:09.409993 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-11-20 09:05:09.416646 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-11-20 09:05:09.418174 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-11-20 09:05:09.424775 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-11-20 09:05:09.426237 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-11-20 09:05:09.432842 INFO::preprocessReads.R/preprocessReadsChunk: done
 done successfully.



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



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



Executing test function test.checkGATKJar  ... Timing stopped at: 0 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= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:05:09.847264 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:05:09.850544 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/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= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:05:10.10432 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:05:10.267994 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-11-20 09:05:10.272032 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:05:10.275536 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/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= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:05:10.619761 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/reads.fastq.gz
 done successfully.



Executing test function test.FastQStreamer.getReads.truncated  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:05:10.819493 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/truncated.fastq.gz
 done successfully.



Executing test function test.FastQStreamer.subsampler.isdeterministic  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:05:12.435767 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:05:12.504907 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-11-20 09:05:12.508523 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:05:12.511973 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:05:12.766299 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:05:12.83471 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-11-20 09:05:12.838355 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:05:12.841898 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/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= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
 done successfully.



Executing test function test.mergeLanes  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:05:13.707083 INFO::preprocessReads.R/preprocessReads: starting...
2024-11-20 09:05:13.713523 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:05:13.717984 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-11-20 09:05:13.72084 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:05:17.292346 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:05:17.294502 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/chunks/chunk_000001/logs/progress.log
2024-11-20 09:05:20.056524 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.046 minutes
2024-11-20 09:05:20.058544 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/chunks/chunk_000002/logs/progress.log
2024-11-20 09:05:22.784333 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.045 minutes
2024-11-20 09:05:22.786328 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/chunks/chunk_000003/logs/progress.log
2024-11-20 09:05:25.538023 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.046 minutes
2024-11-20 09:05:25.606715 DEBUG::tools.R/processChunks: done
2024-11-20 09:05:25.610482 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-11-20 09:05:25.613489 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.adapter_contaminated_1.RData
2024-11-20 09:05:25.616505 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-11-20 09:05:25.618812 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.adapter_contaminated_2.RData
2024-11-20 09:05:25.630057 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-11-20 09:05:25.632839 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.summary_preprocess.tab
2024-11-20 09:05:25.636497 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/bams/processed.aligner_input_1.fastq ...
2024-11-20 09:05:25.643389 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/bams/processed.aligner_input_2.fastq ...
2024-11-20 09:05:25.64914 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/reports/shortReadReport_1 ...
2024-11-20 09:05:27.540304 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/reports/shortReadReport_2 ...
2024-11-20 09:05:29.073425 INFO::preprocessReads.R/preprocessReads: done
2024-11-20 09:05:29.146335 INFO::alignReads.R/alignReads: starting alignment...
2024-11-20 09:05:29.151235 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:05:34.311998 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:05:34.314381 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/chunks/chunk_000001/logs/progress.log
2024-11-20 09:05:36.933051 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-11-20 09:05:36.935467 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/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-11-20 09:05:39.553519 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.044 minutes
2024-11-20 09:05:39.555991 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/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-11-20 09:05:42.20079 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.044 minutes
2024-11-20 09:05:42.204283 DEBUG::tools.R/processChunks: done
2024-11-20 09:05:42.206437 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-11-20 09:05:42.492573 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-11-20 09:05:42.50347 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.summary_alignment.tab
2024-11-20 09:05:42.513704 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.summary_analyzed_bamstats.tab
2024-11-20 09:05:42.516333 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-11-20 09:05:42.769294 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.summary_target_lengths.tab
2024-11-20 09:05:42.83077 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-11-20 09:05:42.83212 INFO::alignReads.R/alignReads: done
2024-11-20 09:05:42.904205 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-11-20 09:05:42.925344 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:05:46.727175 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:05:46.729565 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/chunks/chunk_000001/logs/progress.log
2024-11-20 09:05:49.260628 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.042 minutes
2024-11-20 09:05:49.262844 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/chunks/chunk_000002/logs/progress.log
2024-11-20 09:05:51.836764 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.043 minutes
2024-11-20 09:05:51.839028 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/chunks/chunk_000003/logs/progress.log
2024-11-20 09:05:54.3988 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-11-20 09:05:54.402147 DEBUG::tools.R/processChunks: done
2024-11-20 09:05:54.404406 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-11-20 09:05:54.42158 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.counts_exon.tab
2024-11-20 09:05:54.435482 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.counts_exon_disjoint.tab
2024-11-20 09:05:54.444523 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.counts_gene.tab
2024-11-20 09:05:54.45192 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.counts_gene_coding.tab
2024-11-20 09:05:54.459343 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.counts_gene_exonic.tab
2024-11-20 09:05:54.466716 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.counts_intergenic.tab
2024-11-20 09:05:54.478718 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.counts_intron.tab
2024-11-20 09:05:54.482395 INFO::countGenomicFeatures.R/mergeCounts: done
2024-11-20 09:05:54.490106 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.summary_counts.tab
2024-11-20 09:05:54.492487 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-11-20 09:05:54.861808 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-11-20 09:05:54.863188 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-11-20 09:05:54.938421 INFO::coverage.R/calculateCoverage: starting...
2024-11-20 09:05:54.943106 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:05:58.582252 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:05:58.584569 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/chunks/chunk_000001/logs/progress.log
2024-11-20 09:06:00.779405 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.037 minutes
2024-11-20 09:06:00.781678 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/chunks/chunk_000002/logs/progress.log
2024-11-20 09:06:02.980475 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.037 minutes
2024-11-20 09:06:02.982638 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/chunks/chunk_000003/logs/progress.log
2024-11-20 09:06:05.180221 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.037 minutes
2024-11-20 09:06:05.183709 DEBUG::tools.R/processChunks: done
2024-11-20 09:06:07.004309 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.coverage.RData
2024-11-20 09:06:07.006337 INFO::coverage.R/saveCoverage: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.coverage.bw
2024-11-20 09:06:07.022458 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.summary_coverage.tab
2024-11-20 09:06:07.024485 INFO::coverage.R/calculateCoverage: done
2024-11-20 09:06:07.02683 INFO::analyzeVariants/analyzeVariants: starting ...
2024-11-20 09:06:07.106558 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-11-20 09:06:10.875963 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-11-20 09:06:10.993552 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-11-20 09:06:11.01934 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-11-20 09:06:11.02129 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.raw_variants.RData
2024-11-20 09:06:11.023735 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.filtered_variants.RData
2024-11-20 09:06:11.02562 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-11-20 09:06:11.02715 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-11-20 09:06:11.368739 INFO::analyzeVariants.R/writeVCF: ...done
2024-11-20 09:06:11.514453 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/results/test_pe.summary_variants.tab
2024-11-20 09:06:11.517081 INFO::analyzeVariants/analyzeVariants: done
2024-11-20 09:06:11.520866 INFO::Pipeline run successful.
2024-11-20 09:06:11.691809 INFO::mergeLanes.R/doMergeLanes: starting...
2024-11-20 09:06:11.696954 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-11-20 09:06:11.699868 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.adapter_contaminated_1.RData
2024-11-20 09:06:11.703533 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-11-20 09:06:11.706211 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.adapter_contaminated_2.RData
2024-11-20 09:06:11.720141 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-11-20 09:06:11.723165 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.summary_preprocess.tab
2024-11-20 09:06:11.725967 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-11-20 09:06:12.057777 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-11-20 09:06:12.066981 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.summary_alignment.tab
2024-11-20 09:06:12.078194 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.summary_analyzed_bamstats.tab
2024-11-20 09:06:12.081137 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-11-20 09:06:12.350246 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.summary_target_lengths.tab
2024-11-20 09:06:12.415332 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-11-20 09:06:12.453463 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-11-20 09:06:12.47654 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.counts_exon.tab
2024-11-20 09:06:12.491158 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.counts_exon_disjoint.tab
2024-11-20 09:06:12.499949 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.counts_gene.tab
2024-11-20 09:06:12.507136 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.counts_gene_coding.tab
2024-11-20 09:06:12.514555 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.counts_gene_exonic.tab
2024-11-20 09:06:12.522234 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.counts_intergenic.tab
2024-11-20 09:06:12.536266 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.counts_intron.tab
2024-11-20 09:06:12.540032 INFO::countGenomicFeatures.R/mergeCounts: done
2024-11-20 09:06:12.548038 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.summary_counts.tab
2024-11-20 09:06:12.550396 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-11-20 09:06:12.91935 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-11-20 09:06:15.308862 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.coverage.RData
2024-11-20 09:06:15.3122 INFO::coverage.R/saveCoverage: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.coverage.bw
2024-11-20 09:06:15.329066 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.summary_coverage.tab
2024-11-20 09:06:15.372452 INFO::analyzeVariants/analyzeVariants: starting ...
2024-11-20 09:06:15.455257 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-11-20 09:06:19.405439 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-11-20 09:06:19.527188 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-11-20 09:06:19.554289 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-11-20 09:06:19.556393 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.raw_variants.RData
2024-11-20 09:06:19.558885 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.filtered_variants.RData
2024-11-20 09:06:19.560989 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-11-20 09:06:19.562607 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-11-20 09:06:19.929735 INFO::analyzeVariants.R/writeVCF: ...done
2024-11-20 09:06:20.086101 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.mergeLanes.d8edf5afd649/merged/results/merged.summary_variants.tab
2024-11-20 09:06:20.088865 INFO::analyzeVariants/analyzeVariants: done
2024-11-20 09:06:20.091991 INFO::mergeLanes.R/doMergeLanes: merge lanes successful.
 done successfully.



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



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



Executing test function test.preprocessReads  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:06:20.415426 INFO::preprocessReads.R/preprocessReads: starting...
2024-11-20 09:06:20.436808 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:06:20.456536 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-11-20 09:06:20.459477 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:06:24.093314 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:06:24.095448 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.d8edf1f2d8055/chunks/chunk_000001/logs/progress.log
2024-11-20 09:06:26.870886 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.046 minutes
2024-11-20 09:06:26.94516 DEBUG::tools.R/processChunks: done
2024-11-20 09:06:26.948051 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-11-20 09:06:26.950079 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.d8edf1f2d8055/results/test_pe.adapter_contaminated_1.RData
2024-11-20 09:06:26.952267 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-11-20 09:06:26.954194 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.d8edf1f2d8055/results/test_pe.adapter_contaminated_2.RData
2024-11-20 09:06:26.962369 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-11-20 09:06:26.964867 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.d8edf1f2d8055/results/test_pe.summary_preprocess.tab
2024-11-20 09:06:26.967665 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.d8edf1f2d8055/bams/processed.aligner_input_1.fastq ...
2024-11-20 09:06:26.973789 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.d8edf1f2d8055/bams/processed.aligner_input_2.fastq ...
2024-11-20 09:06:26.97959 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.d8edf1f2d8055/reports/shortReadReport_1 ...
2024-11-20 09:06:28.903791 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.d8edf1f2d8055/reports/shortReadReport_2 ...
2024-11-20 09:06:30.454819 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads.minichunks  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:06:30.752663 INFO::preprocessReads.R/preprocessReads: starting...
2024-11-20 09:06:30.759194 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:06:30.763658 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-11-20 09:06:30.766577 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:06:34.319678 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:06:34.32248 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.minichunks.d8edf21ec5bef/chunks/chunk_000001/logs/progress.log
2024-11-20 09:06:37.08851 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.046 minutes
2024-11-20 09:06:37.090575 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.minichunks.d8edf21ec5bef/chunks/chunk_000002/logs/progress.log
2024-11-20 09:06:39.866979 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.046 minutes
2024-11-20 09:06:39.869002 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.minichunks.d8edf21ec5bef/chunks/chunk_000003/logs/progress.log
2024-11-20 09:06:42.63258 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.046 minutes
2024-11-20 09:06:42.69915 DEBUG::tools.R/processChunks: done
2024-11-20 09:06:42.702696 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-11-20 09:06:42.704967 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.minichunks.d8edf21ec5bef/results/test_pe.adapter_contaminated_1.RData
2024-11-20 09:06:42.707713 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-11-20 09:06:42.709855 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.minichunks.d8edf21ec5bef/results/test_pe.adapter_contaminated_2.RData
2024-11-20 09:06:42.720344 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-11-20 09:06:42.722875 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.minichunks.d8edf21ec5bef/results/test_pe.summary_preprocess.tab
2024-11-20 09:06:42.726348 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.minichunks.d8edf21ec5bef/bams/processed.aligner_input_1.fastq ...
2024-11-20 09:06:42.73295 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.minichunks.d8edf21ec5bef/bams/processed.aligner_input_2.fastq ...
2024-11-20 09:06:42.738954 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.minichunks.d8edf21ec5bef/reports/shortReadReport_1 ...
2024-11-20 09:06:44.525853 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads.minichunks.d8edf21ec5bef/reports/shortReadReport_2 ...
2024-11-20 09:06:46.049015 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads_single_end  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:06:46.289992 INFO::preprocessReads.R/preprocessReads: starting...
2024-11-20 09:06:46.311398 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-11-20 09:06:46.314258 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:06:50.957472 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:06:50.959673 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads_single_end.d8edf5cbe931c/chunks/chunk_000001/logs/progress.log
2024-11-20 09:06:53.423406 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.041 minutes
2024-11-20 09:06:53.4919 DEBUG::tools.R/processChunks: done
2024-11-20 09:06:53.495284 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-11-20 09:06:53.497854 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads_single_end.d8edf5cbe931c/results/test_se.adapter_contaminated_1.RData
2024-11-20 09:06:53.506494 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-11-20 09:06:53.508882 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads_single_end.d8edf5cbe931c/results/test_se.summary_preprocess.tab
2024-11-20 09:06:53.511384 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads_single_end.d8edf5cbe931c/bams/processed.aligner_input_1.fastq ...
2024-11-20 09:06:53.517423 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /home/biocbuild/tmp/Rtmp2ZcOnT/test.preprocessReads_single_end.d8edf5cbe931c/reports/shortReadReport_1 ...
2024-11-20 09:06:55.399852 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/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:06:56.149926 INFO::preprocessReads.R/preprocessReads: starting...
2024-11-20 09:06:56.171497 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_1.fastq.gz
2024-11-20 09:06:56.192368 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_2.fastq.gz
2024-11-20 09:06:56.195441 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:06:59.897191 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:06:59.899382 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-11-20 09:07:02.914673 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.05 minutes
2024-11-20 09:07:02.985798 DEBUG::tools.R/processChunks: done
2024-11-20 09:07:02.988838 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-11-20 09:07:02.990921 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_1.RData
2024-11-20 09:07:02.993196 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-11-20 09:07:02.995184 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_2.RData
2024-11-20 09:07:03.00343 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-11-20 09:07:03.005953 INFO::io.R/saveWithID: saving file= test/results/test.summary_preprocess.tab
2024-11-20 09:07:03.008805 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_1.fastq ...
2024-11-20 09:07:03.015675 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_2.fastq ...
2024-11-20 09:07:03.022291 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_1 ...
2024-11-20 09:07:05.197624 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_2 ...
2024-11-20 09:07:07.068706 INFO::preprocessReads.R/preprocessReads: done
2024-11-20 09:07:07.153393 INFO::alignReads.R/alignReads: starting alignment...
2024-11-20 09:07:07.158207 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:07:11.820831 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:07:11.823286 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-11-20 09:07:17.917992 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.102 minutes
2024-11-20 09:07:17.921549 DEBUG::tools.R/processChunks: done
2024-11-20 09:07:17.923607 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
2024-11-20 09:07:17.961633 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-11-20 09:07:17.970399 INFO::io.R/saveWithID: saving file= test/results/test.summary_alignment.tab
2024-11-20 09:07:17.978387 INFO::io.R/saveWithID: saving file= test/results/test.summary_analyzed_bamstats.tab
2024-11-20 09:07:17.981324 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-11-20 09:07:18.181406 INFO::io.R/saveWithID: saving file= test/results/test.summary_target_lengths.tab
2024-11-20 09:07:18.243067 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-11-20 09:07:18.244463 INFO::alignReads.R/alignReads: done
2024-11-20 09:07:18.320223 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-11-20 09:07:18.340091 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:07:24.07634 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:07:24.078795 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-11-20 09:07:26.697285 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-11-20 09:07:26.70057 DEBUG::tools.R/processChunks: done
2024-11-20 09:07:26.702546 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-11-20 09:07:26.7144 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon.tab
2024-11-20 09:07:26.724235 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon_disjoint.tab
2024-11-20 09:07:26.731375 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene.tab
2024-11-20 09:07:26.736654 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_coding.tab
2024-11-20 09:07:26.741984 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_exonic.tab
2024-11-20 09:07:26.747015 INFO::io.R/saveWithID: saving file= test/results/test.counts_intergenic.tab
2024-11-20 09:07:26.754943 INFO::io.R/saveWithID: saving file= test/results/test.counts_intron.tab
2024-11-20 09:07:26.758982 INFO::countGenomicFeatures.R/mergeCounts: done
2024-11-20 09:07:26.763697 INFO::io.R/saveWithID: saving file= test/results/test.summary_counts.tab
2024-11-20 09:07:26.765971 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-11-20 09:07:27.04786 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-11-20 09:07:27.049104 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-11-20 09:07:27.123015 INFO::coverage.R/calculateCoverage: starting...
2024-11-20 09:07:27.127186 DEBUG::tools.R/processChunks: starting...
2024-11-20 09:07:30.645314 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-11-20 09:07:30.647476 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-11-20 09:07:33.01072 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.039 minutes
2024-11-20 09:07:33.014107 DEBUG::tools.R/processChunks: done
2024-11-20 09:07:34.806132 INFO::io.R/saveWithID: saving file= test/results/test.coverage.RData
2024-11-20 09:07:34.8081 INFO::coverage.R/saveCoverage: saving file= test/results/test.coverage.bw
2024-11-20 09:07:34.914397 INFO::io.R/saveWithID: saving file= test/results/test.summary_coverage.tab
2024-11-20 09:07:34.916246 INFO::coverage.R/calculateCoverage: done
2024-11-20 09:07:34.917921 INFO::analyzeVariants/analyzeVariants: starting ...
2024-11-20 09:07:34.995446 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-11-20 09:07:48.571673 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-11-20 09:07:48.679855 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-11-20 09:07:48.703286 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-11-20 09:07:48.705191 INFO::io.R/saveWithID: saving file= test/results/test.raw_variants.RData
2024-11-20 09:07:48.708237 INFO::io.R/saveWithID: saving file= test/results/test.filtered_variants.RData
2024-11-20 09:07:48.710015 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-11-20 09:07:48.711437 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-11-20 09:07:49.02274 INFO::analyzeVariants.R/writeVCF: ...done
2024-11-20 09:07:49.166048 INFO::io.R/saveWithID: saving file= test/results/test.summary_variants.tab
2024-11-20 09:07:49.168613 INFO::analyzeVariants/analyzeVariants: done
2024-11-20 09:07:49.174425 INFO::Pipeline run successful.
 done successfully.



Executing test function test.calculateTargetLength  ... checkConfig.R/checkConfig.template: loading template config= //home/biocbuild/tmp/Rtmp2ZcOnT/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/config/default-config.txt 
2024-11-20 09:07:49.467696 INFO::io.R/saveWithID: saving file= /home/biocbuild/tmp/Rtmp2ZcOnT/test.calcTargetLengths.d8edf1d8d379e/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 -- Wed Nov 20 09:08:05 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/R/R-4.4.1/site-library/HTSeqGenie/unitTests 
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.alignReads.R 
test.alignReads: (2 checks) ... OK (30.37 seconds)
test.alignReads.sparsechunks: (2 checks) ... OK (18.66 seconds)
test.alignReadsOneSingleEnd: (2 checks) ... OK (0.54 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.analyzeVariants.R 
test.annotateVariants : DEACTIVATED, Skipped annotateVariants() test
test.callVariantsVariantTools.genotype: (2 checks) ... OK (101.5 seconds)
test.wrap.callVariants: (4 checks) ... OK (13.4 seconds)
test.wrap.callVariants.filters: (2 checks) ... OK (29.08 seconds)
test.wrap.callVariants.which: (1 checks) ... OK (4.13 seconds)
test.writeVCF.NULL: (1 checks) ... OK (0.17 seconds)
test.writeVCF.vcfStat: (4 checks) ... OK (0.69 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.bamUtils.R 
test.isFirstFragment: (5 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.buildGenomicFeatures.R 
test.buildCountsGRangesList: (3 checks) ... OK (36.15 seconds)
test.generateSingleGeneDERs: (4 checks) ... OK (34.41 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.calculateCoverage.R 
test.computeCoverage: (9 checks) ... OK (0.98 seconds)
test.isSparse: (5 checks) ... OK (0.13 seconds)
test.mergeCoverage: (1 checks) ... OK (1.73 seconds)
test.mergeCoverage.sparse: (2 checks) ... OK (1.49 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.checkConfig.R 
test.checkConfig.analyzeVariants: (5 checks) ... OK (0.2 seconds)
test.findTemplate: (5 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.config.R 
test.checkConfig: (5 checks) ... OK (0.45 seconds)
test.checkConfig.alignReads: (5 checks) ... OK (0.51 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/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.detectAdapterContam.R 
test.getAdapterSeqs: (5 checks) ... OK (0.05 seconds)
test.isAdapter: (5 checks) ... OK (0.16 seconds)
test.isAdapter3.primeEnd: (1 checks) ... OK (0.12 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.detectRRNA.R 
test.detectRRNA: (1 checks) ... OK (0.32 seconds)
test.detectRRNA.paired_end: (1 checks) ... OK (0.49 seconds)
test.getRRNAIds: (1 checks) ... OK (0.28 seconds)
test.getRRNAIds_random: (1 checks) ... OK (0.19 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.filterQuality.R 
test.filterByLength: (2 checks) ... OK (0.08 seconds)
test.isAboveQualityThresh: (3 checks) ... OK (0.06 seconds)
test.trimTailsByQuality: (4 checks) ... OK (0.05 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/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.21 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/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.io.R 
test.FastQStreamer.getReads.pefq: (1 checks) ... OK (0.26 seconds)
test.FastQStreamer.getReads.pefq.subsample: (1 checks) ... OK (0.5 seconds)
test.FastQStreamer.getReads.segz: (1 checks) ... OK (0.21 seconds)
test.FastQStreamer.getReads.truncated: (1 checks) ... OK (0.24 seconds)
test.FastQStreamer.subsampler.isdeterministic: (3 checks) ... OK (2.05 seconds)
test.createTmpDir: (4 checks) ... OK (0 seconds)
test.detectQualityInFASTQFile: (3 checks) ... OK (0.17 seconds)
test.getObjectFilename: (4 checks) ... OK (0.01 seconds)
test.safeUnlink: (2 checks) ... OK (0.01 seconds)
test.writeAudit: (0 checks) ... OK (0.22 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.mergeLanes.R 
test.mergeLanes: (6 checks) ... OK (66.77 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/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/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.preprocessReads.R 
test.preprocessReads: (5 checks) ... OK (10.34 seconds)
test.preprocessReads.minichunks: (5 checks) ... OK (15.59 seconds)
test.preprocessReads_single_end: (5 checks) ... OK (9.35 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.readRNASeqEnds.R 
test.readRNASeqEnds: (6 checks) ... OK (0.12 seconds)
test.readRNASeqEnds.dupmark: (2 checks) ... OK (0.12 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.reportPipelineQA.R 
test.how_many: (3 checks) ... OK (0 seconds)
test.plotDF: (3 checks) ... OK (0.14 seconds)
test.relativeBarPlot: (2 checks) ... OK (0.05 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.runPipeline.R 
test.runPipeline: (1 checks) ... OK (53.32 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.targetLengths.R 
test.calculateTargetLength: (4 checks) ... OK (0.29 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.tools.R 
test.sclapply: (10 checks) ... OK (15.38 seconds)
test.tryKeepTraceback: (3 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/R/R-4.4.1/site-library/HTSeqGenie/unitTests/runit.trimReads.R 
test.truncateReads: (7 checks) ... OK (0.08 seconds)
test.truncateReads.trim5: (15 checks) ... OK (0.24 seconds) 

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