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

Hostname	OS	Arch (*)	R version	Installed pkgs
nebbiolo2	Linux (Ubuntu 22.04.3 LTS)	x86_64	4.4.0 RC (2024-04-16 r86468) -- "Puppy Cup"	4679
lconway	macOS 12.7.1 Monterey	x86_64	4.4.1 RC (2024-06-06 r86719) -- "Race for Your Life"	4353
Click on any hostname to see more info about the system (e.g. compilers) () as reported by 'uname -p', except on Windows and Mac OS X*

CHECK results for HTSeqGenie on nebbiolo2

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

raw results

Summary

Package: HTSeqGenie

Version: 4.35.0

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

StartedAt: 2024-06-14 00:31:53 -0400 (Fri, 14 Jun 2024)

EndedAt: 2024-06-14 00:45:28 -0400 (Fri, 14 Jun 2024)

EllapsedTime: 814.5 seconds

RetCode: 0

Status: OK

CheckDir: HTSeqGenie.Rcheck

Warnings: 0

Command output

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


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

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

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

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

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

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

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

Installation output

HTSeqGenie.Rcheck/00install.out

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


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

Tests output

HTSeqGenie.Rcheck/tests/doRUnit.Rout


R version 4.4.0 RC (2024-04-16 r86468) -- "Puppy Cup"
Copyright (C) 2024 The R Foundation for Statistical Computing
Platform: x86_64-pc-linux-gnu

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

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

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

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

Attaching package: 'BiocGenerics'

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

    IQR, mad, sd, var, xtabs

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

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

Loading required package: S4Vectors
Loading required package: stats4

Attaching package: 'S4Vectors'

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

    findMatches

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

    I, expand.grid, unname

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

Attaching package: 'Biostrings'

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

    strsplit

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

Attaching package: 'MatrixGenerics'

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

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

Loading required package: Biobase
Welcome to Bioconductor

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


Attaching package: 'Biobase'

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

    rowMedians

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

    anyMissing, rowMedians

Loading required package: VariantAnnotation

Attaching package: 'VariantAnnotation'

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

    tabulate

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


Executing test function test.alignReads  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:37:39.799457 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-14 00:37:39.807228 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:37:39.810457 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-14 00:37:39.812414 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:37:42.3994 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:37:42.400845 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/chunks/chunk_000001/logs/progress.log
2024-06-14 00:37:45.123754 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.045 minutes
2024-06-14 00:37:45.125731 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/chunks/chunk_000002/logs/progress.log
2024-06-14 00:37:47.843123 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.045 minutes
2024-06-14 00:37:47.844597 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/chunks/chunk_000003/logs/progress.log
2024-06-14 00:37:50.559284 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.045 minutes
2024-06-14 00:37:50.587157 DEBUG::tools.R/processChunks: done
2024-06-14 00:37:50.590675 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-14 00:37:50.592807 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/results/test_pe.adapter_contaminated_1.RData
2024-06-14 00:37:50.595275 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-14 00:37:50.596709 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/results/test_pe.adapter_contaminated_2.RData
2024-06-14 00:37:50.605134 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=26 highqual_reads=25 adapter_contam=1 read_length=75 rRNA_contam_reads=0 processed_reads=25 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-06-14 00:37:50.607218 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/results/test_pe.summary_preprocess.tab
2024-06-14 00:37:50.610322 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/bams/processed.aligner_input_1.fastq ...
2024-06-14 00:37:50.614142 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/bams/processed.aligner_input_2.fastq ...
2024-06-14 00:37:50.617067 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/reports/shortReadReport_1 ...
2024-06-14 00:37:51.879635 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/reports/shortReadReport_2 ...
2024-06-14 00:37:52.888051 INFO::preprocessReads.R/preprocessReads: done
2024-06-14 00:37:52.951756 INFO::alignReads.R/alignReads: starting alignment...
2024-06-14 00:37:52.958311 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:37:55.906934 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:37:55.908652 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/chunks/chunk_000001/logs/progress.log
2024-06-14 00:37:58.7301 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.047 minutes
2024-06-14 00:37:58.732719 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/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-06-14 00:38:01.369938 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.044 minutes
2024-06-14 00:38:01.371622 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/chunks/chunk_000003/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-06-14 00:38:03.988871 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.044 minutes
2024-06-14 00:38:03.991232 DEBUG::tools.R/processChunks: done
2024-06-14 00:38:03.992662 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-06-14 00:38:04.209481 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-06-14 00:38:04.218583 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/results/test_pe.summary_alignment.tab
2024-06-14 00:38:04.225827 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/results/test_pe.summary_analyzed_bamstats.tab
2024-06-14 00:38:04.227534 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-06-14 00:38:04.476916 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.alignReads.2772d065ee9e50/results/test_pe.summary_target_lengths.tab
2024-06-14 00:38:04.524407 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-06-14 00:38:04.52539 INFO::alignReads.R/alignReads: done
 done successfully.



Executing test function test.alignReads.sparsechunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:38:04.763864 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-14 00:38:04.768023 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:38:04.847324 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 2 , totnbreads= 26 )
2024-06-14 00:38:04.852381 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:38:04.855569 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-14 00:38:04.857697 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:38:07.739154 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:38:07.74061 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpcyREHj/test.alignReads.sparsechunks.2772d03ca207b1/chunks/chunk_000001/logs/progress.log
2024-06-14 00:38:10.394285 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-06-14 00:38:10.395613 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpcyREHj/test.alignReads.sparsechunks.2772d03ca207b1/chunks/chunk_000002/logs/progress.log
2024-06-14 00:38:13.093136 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.045 minutes
2024-06-14 00:38:13.094579 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpcyREHj/test.alignReads.sparsechunks.2772d03ca207b1/chunks/chunk_000003/logs/progress.log
2024-06-14 00:38:15.836122 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.046 minutes
2024-06-14 00:38:15.838187 DEBUG::tools.R/processChunks: starting chunkid= 4 ; see logfile= /tmp/RtmpcyREHj/test.alignReads.sparsechunks.2772d03ca207b1/chunks/chunk_000004/logs/progress.log
2024-06-14 00:38:18.519095 DEBUG::tools.R/processChunks: done with chunkid= 4 ; elapsed.time= 0.045 minutes
2024-06-14 00:38:18.550588 DEBUG::tools.R/processChunks: done
2024-06-14 00:38:18.553988 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-14 00:38:18.556248 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.alignReads.sparsechunks.2772d03ca207b1/results/test_pe.adapter_contaminated_1.RData
2024-06-14 00:38:18.5591 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-14 00:38:18.560717 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.alignReads.sparsechunks.2772d03ca207b1/results/test_pe.adapter_contaminated_2.RData
2024-06-14 00:38:18.571764 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=2 highqual_reads=1 adapter_contam=0 read_length=75 rRNA_contam_reads=0 processed_reads=1 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-06-14 00:38:18.574415 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.alignReads.sparsechunks.2772d03ca207b1/results/test_pe.summary_preprocess.tab
2024-06-14 00:38:18.578247 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpcyREHj/test.alignReads.sparsechunks.2772d03ca207b1/bams/processed.aligner_input_1.fastq ...
2024-06-14 00:38:18.582517 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpcyREHj/test.alignReads.sparsechunks.2772d03ca207b1/bams/processed.aligner_input_2.fastq ...
2024-06-14 00:38:18.586318 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpcyREHj/test.alignReads.sparsechunks.2772d03ca207b1/reports/shortReadReport_1 ...
2024-06-14 00:38:19.872956 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpcyREHj/test.alignReads.sparsechunks.2772d03ca207b1/reports/shortReadReport_2 ...
2024-06-14 00:38:20.87773 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.alignReadsOneSingleEnd  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:38:21.030071 INFO::alignReads.R/alignReadsChunk: running gsnap...
2024-06-14 00:38:21.036344 INFO::alignReads.R/alignReadsChunk: calling gsnap (from gmapR) with args= -D /home/biocbuild/.local/share/gmap -t 1 -d TP53_demo_3.2.2 --quality-protocol=illumina  -A sam --read-group-id=test_se -m 0 --split-output /tmp/RtmpcyREHj/test.alignReadsOneSingleEnd.2772d0c293a71/bams/test.alignReads /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq 2>&1
2024-06-14 00:38:21.225906 INFO::alignReads.R/createSummaryAlignment: counting unique bam reads...
2024-06-14 00:38:21.313134 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.alignReadsOneSingleEnd.2772d0c293a71/results/test.alignReads.summary_alignment.tab
2024-06-14 00:38:21.353864 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.alignReadsOneSingleEnd.2772d0c293a71/results/test.alignReads.summary_analyzed_bamstats.tab
2024-06-14 00:38:21.355478 INFO::alignReads.R/alignReadsChunk: done
 done successfully.



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



Executing test function test.callVariantsVariantTools.genotype  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:38:21.657363 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.genotype.2772d02c24e9b6/results/test_pe.coverage.RData
2024-06-14 00:38:21.659319 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpcyREHj/test.genotype.2772d02c24e9b6/results/test_pe.coverage.bw
2024-06-14 00:38:21.775916 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.genotype.2772d02c24e9b6/results/test_pe.summary_coverage.tab
2024-06-14 00:38:21.777746 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-14 00:38:32.164189 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-14 00:38:32.242377 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-14 00:38:32.257909 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-14 00:38:32.259321 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.genotype.2772d02c24e9b6/results/test_pe.raw_variants.RData
2024-06-14 00:38:32.261611 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.genotype.2772d02c24e9b6/results/test_pe.filtered_variants.RData
2024-06-14 00:38:32.262878 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-14 00:38:32.264013 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-14 00:38:32.637562 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-14 00:38:32.638903 INFO::analyzeVariants.R/.callGenotypes: calling genotypes...
2024-06-14 00:39:26.114687 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-14 00:39:26.54186 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-14 00:39:26.542796 INFO::analyzeVariants.R/.callGenotypes: done
[W::bcf_hdr_check_sanity] PL should be declared as Number=G
 done successfully.



Executing test function test.wrap.callVariants  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:39:26.974739 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-14 00:39:36.851854 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-14 00:39:36.926762 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-14 00:39:36.942698 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-14 00:39:36.944022 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.wrap.callVariants.2772d0371d04ff/results/test_pe.raw_variants.RData
2024-06-14 00:39:36.946468 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.wrap.callVariants.2772d0371d04ff/results/test_pe.filtered_variants.RData
2024-06-14 00:39:36.947783 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.filters  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:39:37.087598 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-14 00:39:46.994712 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-14 00:39:47.048795 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-14 00:39:47.064564 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-14 00:39:47.065851 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.wrap.callVariants.filters.2772d0560ad129/results/test_pe.raw_variants.RData
2024-06-14 00:39:47.068161 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.wrap.callVariants.filters.2772d0560ad129/results/test_pe.filtered_variants.RData
2024-06-14 00:39:47.069373 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-14 00:39:47.070778 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-14 00:39:56.978247 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-14 00:39:57.0185 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-14 00:39:57.036112 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-14 00:39:57.037664 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.wrap.callVariants.filters.2772d0560ad129/results/test_pe.raw_variants.RData
2024-06-14 00:39:57.04039 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.wrap.callVariants.filters.2772d0560ad129/results/test_pe.filtered_variants.RData
2024-06-14 00:39:57.042504 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.which  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:39:57.300295 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-14 00:39:57.301761 INFO::analyzeVariants.R/buildTallyParam: restricting variant calls using 'which'
2024-06-14 00:40:00.06067 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-14 00:40:00.126739 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-14 00:40:00.14156 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-14 00:40:00.142776 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.wrap.callVariants.which.2772d0428c197e/results/test_pe.raw_variants.RData
2024-06-14 00:40:00.144233 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.wrap.callVariants.which.2772d0428c197e/results/test_pe.filtered_variants.RData
2024-06-14 00:40:00.14539 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.writeVCF.NULL  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:40:00.265775 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-14 00:40:00.266922 INFO::analyzeVariants.R/writeVCF: ...done
 done successfully.



Executing test function test.writeVCF.vcfStat  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:40:01.861058 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-14 00:40:02.04064 INFO::analyzeVariants.R/writeVCF: ...done
 done successfully.



Executing test function test.isFirstFragment  ...  done successfully.



Executing test function test.buildCountsGRangesList  ...   403 genes were dropped because they have exons located on both strands
  of the same reference sequence or on more than one reference sequence,
  so cannot be represented by a single genomic range.
  Use 'single.strand.genes.only=FALSE' to get all the genes in a
  GRangesList object, or use suppressMessages() to suppress this message.
 done successfully.



Executing test function test.generateSingleGeneDERs  ...  done successfully.



Executing test function test.computeCoverage  ...  done successfully.



Executing test function test.isSparse  ...  done successfully.



Executing test function test.mergeCoverage  ... 2024-06-14 00:40:52.300106 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/dsrtlgmk/merged/results/bla.coverage.RData
2024-06-14 00:40:52.302613 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpcyREHj/dsrtlgmk/merged/results/bla.coverage.bw
2024-06-14 00:40:52.373926 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/dsrtlgmk/merged/results/bla.summary_coverage.tab
 done successfully.



Executing test function test.mergeCoverage.sparse  ... 2024-06-14 00:40:53.415424 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/ajmqricw/merged/results/bla.coverage.RData
2024-06-14 00:40:53.416773 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpcyREHj/ajmqricw/merged/results/bla.coverage.bw
2024-06-14 00:40:53.427678 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/ajmqricw/merged/results/bla.summary_coverage.tab
 done successfully.



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



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



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



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



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



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



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



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



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



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



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



Executing test function test.detectRRNA  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:40:54.605916 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-06-14 00:40:54.607037 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmpcyREHj/test.detectRRNA.2772d071eb032e/bams/rRNA_contam/input1.fastq
2024-06-14 00:40:54.610277 INFO::alignReads.R/alignReadsChunk: calling gsnap (from gmapR) with args= -t 0 -D /home/biocbuild/.local/share/gmap -n 1 -d TP53_demo_3.2.2 -A sam -B 2 --pairmax-rna=200000 --split-output /tmp/RtmpcyREHj/test.detectRRNA.2772d071eb032e/bams/rRNA_contam/test_se /tmp/RtmpcyREHj/test.detectRRNA.2772d071eb032e/bams/rRNA_contam/input1.fastq 2>&1
2024-06-14 00:40:54.733307 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-06-14 00:40:54.734244 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.detectRRNA.paired_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:40:54.869828 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-06-14 00:40:54.870831 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmpcyREHj/test.detectRRNA.paired_end.2772d032b6197e/bams/rRNA_contam/input1.fastq
2024-06-14 00:40:54.872316 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmpcyREHj/test.detectRRNA.paired_end.2772d032b6197e/bams/rRNA_contam/input2.fastq
2024-06-14 00:40:54.874408 INFO::alignReads.R/alignReadsChunk: calling gsnap (from gmapR) with args= -t 0 -D /home/biocbuild/.local/share/gmap -n 1 -d TP53_demo_3.2.2 -A sam -B 2 --pairmax-rna=200000 --split-output /tmp/RtmpcyREHj/test.detectRRNA.paired_end.2772d032b6197e/bams/rRNA_contam/test_pe /tmp/RtmpcyREHj/test.detectRRNA.paired_end.2772d032b6197e/bams/rRNA_contam/input1.fastq -a paired /tmp/RtmpcyREHj/test.detectRRNA.paired_end.2772d032b6197e/bams/rRNA_contam/input2.fastq 2>&1
2024-06-14 00:40:55.089866 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-06-14 00:40:55.090861 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.getRRNAIds  ... 2024-06-14 00:40:55.110158 INFO::alignReads.R/alignReadsChunk: calling gsnap (from gmapR) with args= -t 0 -D /home/biocbuild/.local/share/gmap -n 1 -d TP53_demo_3.2.2 -A sam -B 2 --pairmax-rna=200000 --split-output /tmp/RtmpcyREHj/test_get_rRNA_idsilsfqcgm/test_pe /tmp/RtmpcyREHj/test_get_rRNA_idsilsfqcgm/1.fastq -a paired /tmp/RtmpcyREHj/test_get_rRNA_idsilsfqcgm/2.fastq 2>&1
 done successfully.



Executing test function test.getRRNAIds_random  ... 2024-06-14 00:40:55.344231 INFO::alignReads.R/alignReadsChunk: calling gsnap (from gmapR) with args= -t 0 -D /home/biocbuild/.local/share/gmap -n 1 -d TP53_demo_3.2.2 -A sam -B 2 --pairmax-rna=200000 --split-output /tmp/RtmpcyREHj/test_get_rRNAIds_randomitmagzus/test_pe /tmp/RtmpcyREHj/test_get_rRNAIds_randomitmagzus/1.fastq 2>&1
 done successfully.



Executing test function test.filterByLength  ... 2024-06-14 00:40:55.534273 INFO::filterQuality.R/filterQuality: filterByLength...
2024-06-14 00:40:55.535653 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 0.5
2024-06-14 00:40:55.536479 INFO::filterQuality.R/filterByLength: done
2024-06-14 00:40:55.580696 INFO::filterQuality.R/filterQuality: filterByLength...
2024-06-14 00:40:55.58158 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 1
2024-06-14 00:40:55.582357 INFO::filterQuality.R/filterByLength: done
 done successfully.



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



Executing test function test.trimTailsByQuality  ... 2024-06-14 00:40:55.628985 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-06-14 00:40:55.637475 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-06-14 00:40:55.638485 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-06-14 00:40:55.642577 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-06-14 00:40:55.643461 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-06-14 00:40:55.647419 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-06-14 00:40:55.648275 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-06-14 00:40:55.652197 INFO::preprocessReads.R/preprocessReadsChunk: done
 done successfully.



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



Executing test function test.callVariantsGATK.withFiltering  ... Timing stopped at: 0 0 0
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.001 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.001
Error in DEACTIVATED("gatk() tests need gatk.path option set") : 
  gatk() tests need gatk.path option set
 done successfully.



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



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



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



Executing test function test_zipUp  ...  done successfully.



Executing test function test.FastQStreamer.getReads.pefq  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:40:55.928939 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:40:55.931272 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



Executing test function test.FastQStreamer.getReads.pefq.subsample  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:40:56.099636 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:40:56.202929 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-06-14 00:40:56.205608 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:40:56.207684 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



Executing test function test.FastQStreamer.getReads.segz  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:40:56.433401 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/reads.fastq.gz
 done successfully.



Executing test function test.FastQStreamer.getReads.truncated  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:40:56.570452 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/truncated.fastq.gz
 done successfully.



Executing test function test.FastQStreamer.subsampler.isdeterministic  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:40:57.68943 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:40:57.749637 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-06-14 00:40:57.751895 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:40:57.753914 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:40:57.936528 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:40:57.986629 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-06-14 00:40:57.989114 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:40:57.991333 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



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



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



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



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



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



Executing test function test.mergeLanes  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:40:58.631155 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-14 00:40:58.637301 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:40:58.640713 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-14 00:40:58.642919 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:41:01.491781 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:41:01.49322 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/chunks/chunk_000001/logs/progress.log
2024-06-14 00:41:04.108728 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-06-14 00:41:04.110011 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/chunks/chunk_000002/logs/progress.log
2024-06-14 00:41:06.684088 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.043 minutes
2024-06-14 00:41:06.685686 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/chunks/chunk_000003/logs/progress.log
2024-06-14 00:41:09.262352 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-06-14 00:41:09.301897 DEBUG::tools.R/processChunks: done
2024-06-14 00:41:09.304691 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-14 00:41:09.306323 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.adapter_contaminated_1.RData
2024-06-14 00:41:09.308357 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-14 00:41:09.30987 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.adapter_contaminated_2.RData
2024-06-14 00:41:09.317925 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=26 highqual_reads=25 adapter_contam=1 read_length=75 rRNA_contam_reads=0 processed_reads=25 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-06-14 00:41:09.319603 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.summary_preprocess.tab
2024-06-14 00:41:09.321904 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/bams/processed.aligner_input_1.fastq ...
2024-06-14 00:41:09.325484 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/bams/processed.aligner_input_2.fastq ...
2024-06-14 00:41:09.328455 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/reports/shortReadReport_1 ...
2024-06-14 00:41:10.592694 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/reports/shortReadReport_2 ...
2024-06-14 00:41:11.603362 INFO::preprocessReads.R/preprocessReads: done
2024-06-14 00:41:11.679037 INFO::alignReads.R/alignReads: starting alignment...
2024-06-14 00:41:11.683584 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:41:14.519459 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:41:14.521111 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/chunks/chunk_000001/logs/progress.log
2024-06-14 00:41:17.037834 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.042 minutes
2024-06-14 00:41:17.039581 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/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-06-14 00:41:19.582088 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.042 minutes
2024-06-14 00:41:19.584337 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/chunks/chunk_000003/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-06-14 00:41:22.156549 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-06-14 00:41:22.159845 DEBUG::tools.R/processChunks: done
2024-06-14 00:41:22.161767 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-06-14 00:41:22.362647 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-06-14 00:41:22.370462 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.summary_alignment.tab
2024-06-14 00:41:22.377217 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.summary_analyzed_bamstats.tab
2024-06-14 00:41:22.379084 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-06-14 00:41:22.605545 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.summary_target_lengths.tab
2024-06-14 00:41:22.653625 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-06-14 00:41:22.654638 INFO::alignReads.R/alignReads: done
2024-06-14 00:41:22.738657 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-06-14 00:41:22.757964 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:41:25.661196 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:41:25.663011 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/chunks/chunk_000001/logs/progress.log
2024-06-14 00:41:28.093842 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.041 minutes
2024-06-14 00:41:28.095539 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/chunks/chunk_000002/logs/progress.log
2024-06-14 00:41:30.500009 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.04 minutes
2024-06-14 00:41:30.501436 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/chunks/chunk_000003/logs/progress.log
2024-06-14 00:41:32.92076 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.04 minutes
2024-06-14 00:41:32.92415 DEBUG::tools.R/processChunks: done
2024-06-14 00:41:32.926639 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-06-14 00:41:32.946955 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.counts_exon.tab
2024-06-14 00:41:32.965501 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.counts_exon_disjoint.tab
2024-06-14 00:41:32.975929 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.counts_gene.tab
2024-06-14 00:41:32.982255 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.counts_gene_coding.tab
2024-06-14 00:41:32.987898 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.counts_gene_exonic.tab
2024-06-14 00:41:32.993229 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.counts_intergenic.tab
2024-06-14 00:41:33.002417 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.counts_intron.tab
2024-06-14 00:41:33.00566 INFO::countGenomicFeatures.R/mergeCounts: done
2024-06-14 00:41:33.010896 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.summary_counts.tab
2024-06-14 00:41:33.012472 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-06-14 00:41:33.309107 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-06-14 00:41:33.310004 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-06-14 00:41:33.410658 INFO::coverage.R/calculateCoverage: starting...
2024-06-14 00:41:33.415836 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:41:36.512376 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:41:36.514358 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/chunks/chunk_000001/logs/progress.log
2024-06-14 00:41:38.678284 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.036 minutes
2024-06-14 00:41:38.680245 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/chunks/chunk_000002/logs/progress.log
2024-06-14 00:41:40.837955 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.036 minutes
2024-06-14 00:41:40.839558 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/chunks/chunk_000003/logs/progress.log
2024-06-14 00:41:42.998796 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.036 minutes
2024-06-14 00:41:43.001524 DEBUG::tools.R/processChunks: done
2024-06-14 00:41:44.214317 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.coverage.RData
2024-06-14 00:41:44.215641 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.coverage.bw
2024-06-14 00:41:44.226713 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.summary_coverage.tab
2024-06-14 00:41:44.227934 INFO::coverage.R/calculateCoverage: done
2024-06-14 00:41:44.229852 INFO::analyzeVariants/analyzeVariants: starting ...
2024-06-14 00:41:44.331013 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-14 00:41:47.166833 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-14 00:41:47.232944 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-14 00:41:47.247872 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-14 00:41:47.24913 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.raw_variants.RData
2024-06-14 00:41:47.250555 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.filtered_variants.RData
2024-06-14 00:41:47.25169 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-14 00:41:47.252613 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-14 00:41:47.447439 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-14 00:41:47.538252 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/results/test_pe.summary_variants.tab
2024-06-14 00:41:47.540213 INFO::analyzeVariants/analyzeVariants: done
2024-06-14 00:41:47.544646 INFO::Pipeline run successful.
2024-06-14 00:41:47.743344 INFO::mergeLanes.R/doMergeLanes: starting...
2024-06-14 00:41:47.74851 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-14 00:41:47.750682 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.adapter_contaminated_1.RData
2024-06-14 00:41:47.753565 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-14 00:41:47.755578 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.adapter_contaminated_2.RData
2024-06-14 00:41:47.767325 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=26 highqual_reads=25 adapter_contam=1 read_length=75 rRNA_contam_reads=0 processed_reads=25 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-06-14 00:41:47.769631 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.summary_preprocess.tab
2024-06-14 00:41:47.771795 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-06-14 00:41:48.003596 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-06-14 00:41:48.010837 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.summary_alignment.tab
2024-06-14 00:41:48.0186 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.summary_analyzed_bamstats.tab
2024-06-14 00:41:48.020802 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-06-14 00:41:48.263295 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.summary_target_lengths.tab
2024-06-14 00:41:48.315012 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-06-14 00:41:48.351399 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-06-14 00:41:48.373858 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.counts_exon.tab
2024-06-14 00:41:48.387199 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.counts_exon_disjoint.tab
2024-06-14 00:41:48.394912 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.counts_gene.tab
2024-06-14 00:41:48.40079 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.counts_gene_coding.tab
2024-06-14 00:41:48.406548 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.counts_gene_exonic.tab
2024-06-14 00:41:48.412446 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.counts_intergenic.tab
2024-06-14 00:41:48.425 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.counts_intron.tab
2024-06-14 00:41:48.428796 INFO::countGenomicFeatures.R/mergeCounts: done
2024-06-14 00:41:48.435219 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.summary_counts.tab
2024-06-14 00:41:48.437003 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-06-14 00:41:48.656255 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-06-14 00:41:50.523846 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.coverage.RData
2024-06-14 00:41:50.52647 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.coverage.bw
2024-06-14 00:41:50.537756 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.summary_coverage.tab
2024-06-14 00:41:50.570303 INFO::analyzeVariants/analyzeVariants: starting ...
2024-06-14 00:41:50.657997 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-14 00:41:53.981504 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-14 00:41:54.046602 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-14 00:41:54.061554 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-14 00:41:54.062817 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.raw_variants.RData
2024-06-14 00:41:54.064327 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.filtered_variants.RData
2024-06-14 00:41:54.065505 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-14 00:41:54.066433 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-14 00:41:54.260509 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-14 00:41:54.350146 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.mergeLanes.2772d06231fb76/merged/results/merged.summary_variants.tab
2024-06-14 00:41:54.351969 INFO::analyzeVariants/analyzeVariants: done
2024-06-14 00:41:54.354515 INFO::mergeLanes.R/doMergeLanes: merge lanes successful.
 done successfully.



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



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



Executing test function test.preprocessReads  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:41:54.643199 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-14 00:41:54.664723 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:41:54.683375 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-14 00:41:54.685917 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:41:57.628547 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:41:57.629952 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpcyREHj/test.preprocessReads.2772d02a51bd47/chunks/chunk_000001/logs/progress.log
2024-06-14 00:42:00.22073 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.043 minutes
2024-06-14 00:42:00.264252 DEBUG::tools.R/processChunks: done
2024-06-14 00:42:00.266542 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-14 00:42:00.268116 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.preprocessReads.2772d02a51bd47/results/test_pe.adapter_contaminated_1.RData
2024-06-14 00:42:00.269869 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-14 00:42:00.271288 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.preprocessReads.2772d02a51bd47/results/test_pe.adapter_contaminated_2.RData
2024-06-14 00:42:00.277777 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=26 highqual_reads=25 adapter_contam=1 read_length=75 rRNA_contam_reads=0 processed_reads=25 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-06-14 00:42:00.279559 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.preprocessReads.2772d02a51bd47/results/test_pe.summary_preprocess.tab
2024-06-14 00:42:00.281495 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpcyREHj/test.preprocessReads.2772d02a51bd47/bams/processed.aligner_input_1.fastq ...
2024-06-14 00:42:00.285169 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpcyREHj/test.preprocessReads.2772d02a51bd47/bams/processed.aligner_input_2.fastq ...
2024-06-14 00:42:00.288202 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpcyREHj/test.preprocessReads.2772d02a51bd47/reports/shortReadReport_1 ...
2024-06-14 00:42:01.550003 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpcyREHj/test.preprocessReads.2772d02a51bd47/reports/shortReadReport_2 ...
2024-06-14 00:42:02.552993 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads.minichunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:42:02.77283 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-14 00:42:02.778498 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:42:02.781769 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-14 00:42:02.783885 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:42:05.692161 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:42:05.693586 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpcyREHj/test.preprocessReads.minichunks.2772d010cfa3c5/chunks/chunk_000001/logs/progress.log
2024-06-14 00:42:08.234879 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.042 minutes
2024-06-14 00:42:08.236208 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpcyREHj/test.preprocessReads.minichunks.2772d010cfa3c5/chunks/chunk_000002/logs/progress.log
2024-06-14 00:42:10.802972 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.043 minutes
2024-06-14 00:42:10.80514 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpcyREHj/test.preprocessReads.minichunks.2772d010cfa3c5/chunks/chunk_000003/logs/progress.log
2024-06-14 00:42:13.374844 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-06-14 00:42:13.42335 DEBUG::tools.R/processChunks: done
2024-06-14 00:42:13.426453 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-14 00:42:13.428298 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.preprocessReads.minichunks.2772d010cfa3c5/results/test_pe.adapter_contaminated_1.RData
2024-06-14 00:42:13.430562 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-14 00:42:13.432244 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.preprocessReads.minichunks.2772d010cfa3c5/results/test_pe.adapter_contaminated_2.RData
2024-06-14 00:42:13.441258 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=26 highqual_reads=25 adapter_contam=1 read_length=75 rRNA_contam_reads=0 processed_reads=25 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-06-14 00:42:13.443086 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.preprocessReads.minichunks.2772d010cfa3c5/results/test_pe.summary_preprocess.tab
2024-06-14 00:42:13.445559 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpcyREHj/test.preprocessReads.minichunks.2772d010cfa3c5/bams/processed.aligner_input_1.fastq ...
2024-06-14 00:42:13.450065 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpcyREHj/test.preprocessReads.minichunks.2772d010cfa3c5/bams/processed.aligner_input_2.fastq ...
2024-06-14 00:42:13.453158 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpcyREHj/test.preprocessReads.minichunks.2772d010cfa3c5/reports/shortReadReport_1 ...
2024-06-14 00:42:14.74414 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpcyREHj/test.preprocessReads.minichunks.2772d010cfa3c5/reports/shortReadReport_2 ...
2024-06-14 00:42:15.762922 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads_single_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:42:16.01525 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-14 00:42:16.053315 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-14 00:42:16.056517 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:42:19.0909 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:42:19.092409 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpcyREHj/test.preprocessReads_single_end.2772d06eda2109/chunks/chunk_000001/logs/progress.log
2024-06-14 00:42:21.440984 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.039 minutes
2024-06-14 00:42:21.450393 DEBUG::tools.R/processChunks: done
2024-06-14 00:42:21.452816 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-14 00:42:21.454326 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.preprocessReads_single_end.2772d06eda2109/results/test_se.adapter_contaminated_1.RData
2024-06-14 00:42:21.461274 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=26 highqual_reads=25 adapter_contam=1 read_length=75 rRNA_contam_reads=0 processed_reads=25 input_min_read_length=75 input_max_read_length=75 processed_min_read_length=75 processed_max_read_length=75
2024-06-14 00:42:21.462972 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.preprocessReads_single_end.2772d06eda2109/results/test_se.summary_preprocess.tab
2024-06-14 00:42:21.464869 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpcyREHj/test.preprocessReads_single_end.2772d06eda2109/bams/processed.aligner_input_1.fastq ...
2024-06-14 00:42:21.468128 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpcyREHj/test.preprocessReads_single_end.2772d06eda2109/reports/shortReadReport_1 ...
2024-06-14 00:42:22.752119 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



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



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



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



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



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



Executing test function test.runPipeline  ... checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:42:23.682393 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-14 00:42:23.688711 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_1.fastq.gz
2024-06-14 00:42:23.692593 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_2.fastq.gz
2024-06-14 00:42:23.69493 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:42:31.187771 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:42:31.191662 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-06-14 00:42:35.351889 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.069 minutes
2024-06-14 00:42:35.555448 DEBUG::tools.R/processChunks: done
2024-06-14 00:42:35.577385 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-14 00:42:35.581182 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_1.RData
2024-06-14 00:42:35.58499 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-14 00:42:35.588096 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_2.RData
2024-06-14 00:42:35.618776 INFO::preprocessReads.R/mergeSummaryPreprocess: total_reads=2500 highqual_reads=2500 adapter_contam=0 read_length=100 rRNA_contam_reads=0 processed_reads=2500 input_min_read_length=100 input_max_read_length=100 processed_min_read_length=71 processed_max_read_length=100
2024-06-14 00:42:35.622678 INFO::io.R/saveWithID: saving file= test/results/test.summary_preprocess.tab
2024-06-14 00:42:35.644381 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_1.fastq ...
2024-06-14 00:42:35.678951 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_2.fastq ...
2024-06-14 00:42:35.710436 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_1 ...
2024-06-14 00:42:40.731335 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_2 ...
2024-06-14 00:42:43.345554 INFO::preprocessReads.R/preprocessReads: done
2024-06-14 00:42:43.76657 INFO::alignReads.R/alignReads: starting alignment...
2024-06-14 00:42:43.793051 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:42:49.51371 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:42:49.517128 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
[bam_translate] PG tag "A" on read "HISEQ1:109:D093LACXX:4:2205:16499:6611" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "HISEQ1:109:D093LACXX:4:1206:17367:135118" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "HISEQ1:109:D093LACXX:4:1304:1838:53573" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "HISEQ1:109:D093LACXX:4:2303:2956:116587" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "M" on read "HISEQ1:109:D093LACXX:4:2205:16499:6611" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "T" on read "HISEQ1:109:D093LACXX:4:1206:20028:108227" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "T" on read "HISEQ1:109:D093LACXX:4:1207:19518:143960" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "T" on read "HISEQ1:109:D093LACXX:4:2207:4065:173048" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-06-14 00:42:55.647728 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.102 minutes
2024-06-14 00:42:55.652272 DEBUG::tools.R/processChunks: done
2024-06-14 00:42:55.65525 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
2024-06-14 00:42:55.70798 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-06-14 00:42:55.720251 INFO::io.R/saveWithID: saving file= test/results/test.summary_alignment.tab
2024-06-14 00:42:55.730108 INFO::io.R/saveWithID: saving file= test/results/test.summary_analyzed_bamstats.tab
2024-06-14 00:42:55.734256 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-06-14 00:42:56.023272 INFO::io.R/saveWithID: saving file= test/results/test.summary_target_lengths.tab
2024-06-14 00:42:56.111972 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-06-14 00:42:56.114399 INFO::alignReads.R/alignReads: done
2024-06-14 00:42:56.33886 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-06-14 00:42:56.366156 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:43:01.064029 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:43:01.065979 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-06-14 00:43:04.229969 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.053 minutes
2024-06-14 00:43:04.23404 DEBUG::tools.R/processChunks: done
2024-06-14 00:43:04.236821 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-06-14 00:43:04.25256 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon.tab
2024-06-14 00:43:04.268134 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon_disjoint.tab
2024-06-14 00:43:04.280739 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene.tab
2024-06-14 00:43:04.288754 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_coding.tab
2024-06-14 00:43:04.296273 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_exonic.tab
2024-06-14 00:43:04.303958 INFO::io.R/saveWithID: saving file= test/results/test.counts_intergenic.tab
2024-06-14 00:43:04.316285 INFO::io.R/saveWithID: saving file= test/results/test.counts_intron.tab
2024-06-14 00:43:04.325079 INFO::countGenomicFeatures.R/mergeCounts: done
2024-06-14 00:43:04.332458 INFO::io.R/saveWithID: saving file= test/results/test.summary_counts.tab
2024-06-14 00:43:04.336177 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-06-14 00:43:04.711468 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-06-14 00:43:04.713297 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-06-14 00:43:04.906977 INFO::coverage.R/calculateCoverage: starting...
2024-06-14 00:43:04.914971 DEBUG::tools.R/processChunks: starting...
2024-06-14 00:43:09.386172 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-14 00:43:09.389227 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-06-14 00:43:11.722437 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.039 minutes
2024-06-14 00:43:11.725105 DEBUG::tools.R/processChunks: done
2024-06-14 00:43:13.11441 INFO::io.R/saveWithID: saving file= test/results/test.coverage.RData
2024-06-14 00:43:13.116053 INFO::coverage.R/saveCoverage: saving file= test/results/test.coverage.bw
2024-06-14 00:43:13.196776 INFO::io.R/saveWithID: saving file= test/results/test.summary_coverage.tab
2024-06-14 00:43:13.198148 INFO::coverage.R/calculateCoverage: done
2024-06-14 00:43:13.199676 INFO::analyzeVariants/analyzeVariants: starting ...
2024-06-14 00:43:13.315247 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-14 00:43:24.154158 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-14 00:43:24.223864 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-14 00:43:24.238429 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-14 00:43:24.239628 INFO::io.R/saveWithID: saving file= test/results/test.raw_variants.RData
2024-06-14 00:43:24.242169 INFO::io.R/saveWithID: saving file= test/results/test.filtered_variants.RData
2024-06-14 00:43:24.243387 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-14 00:43:24.244287 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-14 00:43:24.441634 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-14 00:43:24.533947 INFO::io.R/saveWithID: saving file= test/results/test.summary_variants.tab
2024-06-14 00:43:24.535963 INFO::analyzeVariants/analyzeVariants: done
2024-06-14 00:43:24.542603 INFO::Pipeline run successful.
 done successfully.



Executing test function test.calculateTargetLength  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpcyREHj/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-14 00:43:24.791897 INFO::io.R/saveWithID: saving file= /tmp/RtmpcyREHj/test.calcTargetLengths.2772d079f12dda/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 -- Fri Jun 14 00:43:38 2024 
*********************************************** 
Number of test functions: 61 
Number of deactivated test functions: 10 
Number of errors: 0 
Number of failures: 0 

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



Details 
*************************** 
Test Suite: HTSeqGenie unit testing 
Test function regexp: ^test.+ 
Test file regexp: ^runit.+\.[rR]$ 
Involved directory: 
/home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests 
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.alignReads.R 
test.alignReads: (2 checks) ... OK (26.07 seconds)
test.alignReads.sparsechunks: (2 checks) ... OK (16.34 seconds)
test.alignReadsOneSingleEnd: (2 checks) ... OK (0.47 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.analyzeVariants.R 
test.annotateVariants : DEACTIVATED, Skipped annotateVariants() test
test.callVariantsVariantTools.genotype: (2 checks) ... OK (65.48 seconds)
test.wrap.callVariants: (4 checks) ... OK (10.1 seconds)
test.wrap.callVariants.filters: (2 checks) ... OK (20.09 seconds)
test.wrap.callVariants.which: (1 checks) ... OK (3.1 seconds)
test.writeVCF.NULL: (1 checks) ... OK (0.12 seconds)
test.writeVCF.vcfStat: (4 checks) ... OK (1.86 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.bamUtils.R 
test.isFirstFragment: (5 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.buildGenomicFeatures.R 
test.buildCountsGRangesList: (3 checks) ... OK (25.42 seconds)
test.generateSingleGeneDERs: (4 checks) ... OK (22.58 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.calculateCoverage.R 
test.computeCoverage: (9 checks) ... OK (0.66 seconds)
test.isSparse: (5 checks) ... OK (0.09 seconds)
test.mergeCoverage: (1 checks) ... OK (1.49 seconds)
test.mergeCoverage.sparse: (2 checks) ... OK (1.07 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.checkConfig.R 
test.checkConfig.analyzeVariants: (5 checks) ... OK (0.13 seconds)
test.findTemplate: (5 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.config.R 
test.checkConfig: (5 checks) ... OK (0.31 seconds)
test.checkConfig.alignReads: (5 checks) ... OK (0.34 seconds)
test.getConfig: (14 checks) ... OK (0 seconds)
test.loadConfig: (2 checks) ... OK (0 seconds)
test.parseDCF: (7 checks) ... OK (0 seconds)
test.updateConfig: (1 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.detectAdapterContam.R 
test.getAdapterSeqs: (5 checks) ... OK (0.04 seconds)
test.isAdapter: (5 checks) ... OK (0.11 seconds)
test.isAdapter3.primeEnd: (1 checks) ... OK (0.07 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.detectRRNA.R 
test.detectRRNA: (1 checks) ... OK (0.26 seconds)
test.detectRRNA.paired_end: (1 checks) ... OK (0.36 seconds)
test.getRRNAIds: (1 checks) ... OK (0.23 seconds)
test.getRRNAIds_random: (1 checks) ... OK (0.2 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.filterQuality.R 
test.filterByLength: (2 checks) ... OK (0.05 seconds)
test.isAboveQualityThresh: (3 checks) ... OK (0.04 seconds)
test.trimTailsByQuality: (4 checks) ... OK (0.03 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.gatk.R 
test.callVariantsGATK : DEACTIVATED, callVariantsGATK() tests need gatk.path option set
test.callVariantsGATK.withFiltering : DEACTIVATED, callVariantsGATK() tests need gatk.path option set
test.checkGATKJar : DEACTIVATED, checkGATKJar() test needs gatk.path option set
test.excludeVariantsByRegion: (3 checks) ... OK (0.14 seconds)
test.gatk : DEACTIVATED, gatk() tests need gatk.path option set
test.realignIndels : DEACTIVATED, test.realignIndels() tests need gatk.path option set
test.realignIndelsGATK : DEACTIVATED, realignIndelsGATK() tests need gatk.path option set
test.realignIndelsGATK.parallel : DEACTIVATED, realignIndelsGATK() tests need gatk.path option set
test_zipUp: (3 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.io.R 
test.FastQStreamer.getReads.pefq: (1 checks) ... OK (0.18 seconds)
test.FastQStreamer.getReads.pefq.subsample: (1 checks) ... OK (0.33 seconds)
test.FastQStreamer.getReads.segz: (1 checks) ... OK (0.14 seconds)
test.FastQStreamer.getReads.truncated: (1 checks) ... OK (0.16 seconds)
test.FastQStreamer.subsampler.isdeterministic: (3 checks) ... OK (1.46 seconds)
test.createTmpDir: (4 checks) ... OK (0 seconds)
test.detectQualityInFASTQFile: (3 checks) ... OK (0.11 seconds)
test.getObjectFilename: (4 checks) ... OK (0 seconds)
test.safeUnlink: (2 checks) ... OK (0 seconds)
test.writeAudit: (0 checks) ... OK (0.15 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.mergeLanes.R 
test.mergeLanes: (6 checks) ... OK (56.05 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.picard.R 
test.markDuplicates : DEACTIVATED, Skipped markDuplicates() test
test.markDuplicates_w_outfile : DEACTIVATED, Skipped markDuplicates() test
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.preprocessReads.R 
test.preprocessReads: (5 checks) ... OK (8.16 seconds)
test.preprocessReads.minichunks: (5 checks) ... OK (13.21 seconds)
test.preprocessReads_single_end: (5 checks) ... OK (6.99 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.readRNASeqEnds.R 
test.readRNASeqEnds: (6 checks) ... OK (0.11 seconds)
test.readRNASeqEnds.dupmark: (2 checks) ... OK (0.09 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.reportPipelineQA.R 
test.how_many: (3 checks) ... OK (0 seconds)
test.plotDF: (3 checks) ... OK (0.22 seconds)
test.relativeBarPlot: (2 checks) ... OK (0.16 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.runPipeline.R 
test.runPipeline: (1 checks) ... OK (61.21 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.targetLengths.R 
test.calculateTargetLength: (4 checks) ... OK (0.25 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.tools.R 
test.sclapply: (10 checks) ... OK (13.56 seconds)
test.tryKeepTraceback: (3 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.20-bioc/R/site-library/HTSeqGenie/unitTests/runit.trimReads.R 
test.truncateReads: (7 checks) ... OK (0.05 seconds)
test.truncateReads.trim5: (15 checks) ... OK (0.17 seconds) 

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

Example timings

HTSeqGenie.Rcheck/HTSeqGenie-Ex.timings

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