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

Hostname	OS	Arch (*)	R version	Installed pkgs
nebbiolo1	Linux (Ubuntu 22.04.3 LTS)	x86_64	4.4.0 (2024-04-24) -- "Puppy Cup"	4757
palomino3	Windows Server 2022 Datacenter	x64	4.4.0 (2024-04-24 ucrt) -- "Puppy Cup"	4491
Click on any hostname to see more info about the system (e.g. compilers) () as reported by 'uname -p', except on Windows and Mac OS X*

CHECK results for HTSeqGenie on nebbiolo1

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

raw results

Summary

Package: HTSeqGenie

Version: 4.34.0

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

StartedAt: 2024-06-13 00:03:08 -0400 (Thu, 13 Jun 2024)

EndedAt: 2024-06-13 00:17:13 -0400 (Thu, 13 Jun 2024)

EllapsedTime: 844.8 seconds

RetCode: 0

Status: OK

CheckDir: HTSeqGenie.Rcheck

Warnings: 0

Command output

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


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

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

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

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

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

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

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

Installation output

HTSeqGenie.Rcheck/00install.out

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


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

Tests output

HTSeqGenie.Rcheck/tests/doRUnit.Rout


R version 4.4.0 (2024-04-24) -- "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/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:09:09.686825 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-13 00:09:09.699187 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:09:09.704681 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-13 00:09:09.70774 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:09:12.852612 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:09:12.854111 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/chunks/chunk_000001/logs/progress.log
2024-06-13 00:09:15.58416 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.045 minutes
2024-06-13 00:09:15.585928 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/chunks/chunk_000002/logs/progress.log
2024-06-13 00:09:18.34458 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.046 minutes
2024-06-13 00:09:18.346007 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/chunks/chunk_000003/logs/progress.log
2024-06-13 00:09:21.086056 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.046 minutes
2024-06-13 00:09:21.11459 DEBUG::tools.R/processChunks: done
2024-06-13 00:09:21.118283 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-13 00:09:21.120358 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/results/test_pe.adapter_contaminated_1.RData
2024-06-13 00:09:21.122974 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-13 00:09:21.124446 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/results/test_pe.adapter_contaminated_2.RData
2024-06-13 00:09:21.133028 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-13 00:09:21.135173 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/results/test_pe.summary_preprocess.tab
2024-06-13 00:09:21.1383 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/bams/processed.aligner_input_1.fastq ...
2024-06-13 00:09:21.142065 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/bams/processed.aligner_input_2.fastq ...
2024-06-13 00:09:21.144952 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/reports/shortReadReport_1 ...
2024-06-13 00:09:22.468467 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/reports/shortReadReport_2 ...
2024-06-13 00:09:23.473261 INFO::preprocessReads.R/preprocessReads: done
2024-06-13 00:09:23.544797 INFO::alignReads.R/alignReads: starting alignment...
2024-06-13 00:09:23.551389 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:09:26.914055 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:09:26.915859 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/chunks/chunk_000001/logs/progress.log
2024-06-13 00:09:29.817943 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.048 minutes
2024-06-13 00:09:29.81986 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/chunks/chunk_000002/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-06-13 00:09:32.542177 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.045 minutes
2024-06-13 00:09:32.544174 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/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-13 00:09:35.166572 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.044 minutes
2024-06-13 00:09:35.169864 DEBUG::tools.R/processChunks: done
2024-06-13 00:09:35.171875 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "T" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-06-13 00:09:35.391377 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-06-13 00:09:35.399692 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/results/test_pe.summary_alignment.tab
2024-06-13 00:09:35.40658 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/results/test_pe.summary_analyzed_bamstats.tab
2024-06-13 00:09:35.408236 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-06-13 00:09:35.653946 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.alignReads.30d29e9b7e06f/results/test_pe.summary_target_lengths.tab
2024-06-13 00:09:35.701001 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-06-13 00:09:35.702114 INFO::alignReads.R/alignReads: done
 done successfully.



Executing test function test.alignReads.sparsechunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:09:35.948911 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-13 00:09:35.95253 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:09:36.019149 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 2 , totnbreads= 26 )
2024-06-13 00:09:36.023842 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:09:36.026727 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-13 00:09:36.028692 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:09:39.17555 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:09:39.177464 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpMMnlZB/test.alignReads.sparsechunks.30d29e12f15c3/chunks/chunk_000001/logs/progress.log
2024-06-13 00:09:41.884124 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.045 minutes
2024-06-13 00:09:41.885618 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpMMnlZB/test.alignReads.sparsechunks.30d29e12f15c3/chunks/chunk_000002/logs/progress.log
2024-06-13 00:09:44.579055 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.045 minutes
2024-06-13 00:09:44.580655 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpMMnlZB/test.alignReads.sparsechunks.30d29e12f15c3/chunks/chunk_000003/logs/progress.log
2024-06-13 00:09:47.377132 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.047 minutes
2024-06-13 00:09:47.378551 DEBUG::tools.R/processChunks: starting chunkid= 4 ; see logfile= /tmp/RtmpMMnlZB/test.alignReads.sparsechunks.30d29e12f15c3/chunks/chunk_000004/logs/progress.log
2024-06-13 00:09:50.050603 DEBUG::tools.R/processChunks: done with chunkid= 4 ; elapsed.time= 0.045 minutes
2024-06-13 00:09:50.089566 DEBUG::tools.R/processChunks: done
2024-06-13 00:09:50.093163 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-13 00:09:50.095556 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.alignReads.sparsechunks.30d29e12f15c3/results/test_pe.adapter_contaminated_1.RData
2024-06-13 00:09:50.099073 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-13 00:09:50.1009 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.alignReads.sparsechunks.30d29e12f15c3/results/test_pe.adapter_contaminated_2.RData
2024-06-13 00:09:50.111577 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-13 00:09:50.114046 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.alignReads.sparsechunks.30d29e12f15c3/results/test_pe.summary_preprocess.tab
2024-06-13 00:09:50.117783 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpMMnlZB/test.alignReads.sparsechunks.30d29e12f15c3/bams/processed.aligner_input_1.fastq ...
2024-06-13 00:09:50.121842 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpMMnlZB/test.alignReads.sparsechunks.30d29e12f15c3/bams/processed.aligner_input_2.fastq ...
2024-06-13 00:09:50.125701 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpMMnlZB/test.alignReads.sparsechunks.30d29e12f15c3/reports/shortReadReport_1 ...
2024-06-13 00:09:51.368801 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpMMnlZB/test.alignReads.sparsechunks.30d29e12f15c3/reports/shortReadReport_2 ...
2024-06-13 00:09:52.313332 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.alignReadsOneSingleEnd  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:09:52.473854 INFO::alignReads.R/alignReadsChunk: running gsnap...
2024-06-13 00:09:52.478322 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/RtmpMMnlZB/test.alignReadsOneSingleEnd.30d29e8c32a5d/bams/test.alignReads /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq 2>&1
2024-06-13 00:09:52.678276 INFO::alignReads.R/createSummaryAlignment: counting unique bam reads...
2024-06-13 00:09:52.769392 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.alignReadsOneSingleEnd.30d29e8c32a5d/results/test.alignReads.summary_alignment.tab
2024-06-13 00:09:52.811458 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.alignReadsOneSingleEnd.30d29e8c32a5d/results/test.alignReads.summary_analyzed_bamstats.tab
2024-06-13 00:09:52.813097 INFO::alignReads.R/alignReadsChunk: done
 done successfully.



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



Executing test function test.callVariantsVariantTools.genotype  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:09:53.119554 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.genotype.30d29e5bec59a/results/test_pe.coverage.RData
2024-06-13 00:09:53.121516 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpMMnlZB/test.genotype.30d29e5bec59a/results/test_pe.coverage.bw
2024-06-13 00:09:53.234713 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.genotype.30d29e5bec59a/results/test_pe.summary_coverage.tab
2024-06-13 00:09:53.236489 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-13 00:10:03.750145 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-13 00:10:03.867618 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-13 00:10:03.891859 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-13 00:10:03.894256 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.genotype.30d29e5bec59a/results/test_pe.raw_variants.RData
2024-06-13 00:10:03.897511 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.genotype.30d29e5bec59a/results/test_pe.filtered_variants.RData
2024-06-13 00:10:03.899758 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-13 00:10:03.901447 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-13 00:10:04.429908 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-13 00:10:04.431797 INFO::analyzeVariants.R/.callGenotypes: calling genotypes...
2024-06-13 00:11:00.813075 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-13 00:11:01.251035 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-13 00:11:01.252032 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/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:11:01.703101 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-13 00:11:12.291176 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-13 00:11:12.368756 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-13 00:11:12.386346 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-13 00:11:12.387848 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.wrap.callVariants.30d29e7310c04f/results/test_pe.raw_variants.RData
2024-06-13 00:11:12.390237 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.wrap.callVariants.30d29e7310c04f/results/test_pe.filtered_variants.RData
2024-06-13 00:11:12.391601 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.filters  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:11:12.545705 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-13 00:11:22.688226 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-13 00:11:22.757829 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-13 00:11:22.775135 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-13 00:11:22.776572 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.wrap.callVariants.filters.30d29e738dc389/results/test_pe.raw_variants.RData
2024-06-13 00:11:22.779002 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.wrap.callVariants.filters.30d29e738dc389/results/test_pe.filtered_variants.RData
2024-06-13 00:11:22.780295 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-13 00:11:22.781879 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-13 00:11:33.16828 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-13 00:11:33.205693 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-13 00:11:33.221887 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-13 00:11:33.223242 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.wrap.callVariants.filters.30d29e738dc389/results/test_pe.raw_variants.RData
2024-06-13 00:11:33.225745 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.wrap.callVariants.filters.30d29e738dc389/results/test_pe.filtered_variants.RData
2024-06-13 00:11:33.227718 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.wrap.callVariants.which  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:11:33.498648 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-13 00:11:33.500189 INFO::analyzeVariants.R/buildTallyParam: restricting variant calls using 'which'
2024-06-13 00:11:36.295057 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-13 00:11:36.372339 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-13 00:11:36.38755 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-13 00:11:36.388871 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.wrap.callVariants.which.30d29ee013ea/results/test_pe.raw_variants.RData
2024-06-13 00:11:36.390426 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.wrap.callVariants.which.30d29ee013ea/results/test_pe.filtered_variants.RData
2024-06-13 00:11:36.391631 INFO::analyzeVariants.R/wrap.callVariants: ...done
 done successfully.



Executing test function test.writeVCF.NULL  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:11:36.531768 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-13 00:11:36.533085 INFO::analyzeVariants.R/writeVCF: ...done
 done successfully.



Executing test function test.writeVCF.vcfStat  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:11:38.29804 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-13 00:11:38.494783 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-13 00:12:31.10603 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/hljmekno/merged/results/bla.coverage.RData
2024-06-13 00:12:31.108753 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpMMnlZB/hljmekno/merged/results/bla.coverage.bw
2024-06-13 00:12:31.182473 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/hljmekno/merged/results/bla.summary_coverage.tab
 done successfully.



Executing test function test.mergeCoverage.sparse  ... 2024-06-13 00:12:32.391829 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/wqbltnho/merged/results/bla.coverage.RData
2024-06-13 00:12:32.393441 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpMMnlZB/wqbltnho/merged/results/bla.coverage.bw
2024-06-13 00:12:32.404361 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/wqbltnho/merged/results/bla.summary_coverage.tab
 done successfully.



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



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



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



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



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



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



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



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



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



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



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



Executing test function test.detectRRNA  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:12:33.67889 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-06-13 00:12:33.68007 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmpMMnlZB/test.detectRRNA.30d29ece9e932/bams/rRNA_contam/input1.fastq
2024-06-13 00:12:33.683581 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/RtmpMMnlZB/test.detectRRNA.30d29ece9e932/bams/rRNA_contam/test_se /tmp/RtmpMMnlZB/test.detectRRNA.30d29ece9e932/bams/rRNA_contam/input1.fastq 2>&1
2024-06-13 00:12:33.947669 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-06-13 00:12:33.948622 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.detectRRNA.paired_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:12:34.095295 INFO::detectRRNA.R/detectRRNA: searching for rRNA contamination...
2024-06-13 00:12:34.096261 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmpMMnlZB/test.detectRRNA.paired_end.30d29e64068955/bams/rRNA_contam/input1.fastq
2024-06-13 00:12:34.097676 INFO::io.R/writeFastQFiles: writing filename= /tmp/RtmpMMnlZB/test.detectRRNA.paired_end.30d29e64068955/bams/rRNA_contam/input2.fastq
2024-06-13 00:12:34.099805 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/RtmpMMnlZB/test.detectRRNA.paired_end.30d29e64068955/bams/rRNA_contam/test_pe /tmp/RtmpMMnlZB/test.detectRRNA.paired_end.30d29e64068955/bams/rRNA_contam/input1.fastq -a paired /tmp/RtmpMMnlZB/test.detectRRNA.paired_end.30d29e64068955/bams/rRNA_contam/input2.fastq 2>&1
2024-06-13 00:12:34.380137 INFO::detectRRNA.R/detectRRNA: contaminated fraction= 1
2024-06-13 00:12:34.381138 INFO::detectRRNA.R/detectRRNA: done
 done successfully.



Executing test function test.getRRNAIds  ... 2024-06-13 00:12:34.399323 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/RtmpMMnlZB/test_get_rRNA_idszcqkjuxs/test_pe /tmp/RtmpMMnlZB/test_get_rRNA_idszcqkjuxs/1.fastq -a paired /tmp/RtmpMMnlZB/test_get_rRNA_idszcqkjuxs/2.fastq 2>&1
 done successfully.



Executing test function test.getRRNAIds_random  ... 2024-06-13 00:12:34.708836 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/RtmpMMnlZB/test_get_rRNAIds_randomlpexsbij/test_pe /tmp/RtmpMMnlZB/test_get_rRNAIds_randomlpexsbij/1.fastq 2>&1
 done successfully.



Executing test function test.filterByLength  ... 2024-06-13 00:12:34.94924 INFO::filterQuality.R/filterQuality: filterByLength...
2024-06-13 00:12:34.950792 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 0.5
2024-06-13 00:12:34.951723 INFO::filterQuality.R/filterByLength: done
2024-06-13 00:12:35.000769 INFO::filterQuality.R/filterQuality: filterByLength...
2024-06-13 00:12:35.001765 INFO::filterQuality.R/filterByLength: fraction of filtered short reads= 1
2024-06-13 00:12:35.002689 INFO::filterQuality.R/filterByLength: done
 done successfully.



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



Executing test function test.trimTailsByQuality  ... 2024-06-13 00:12:35.057295 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-06-13 00:12:35.067378 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-06-13 00:12:35.068635 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-06-13 00:12:35.074452 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-06-13 00:12:35.075665 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-06-13 00:12:35.080639 INFO::preprocessReads.R/preprocessReadsChunk: done
2024-06-13 00:12:35.081664 INFO::preprocessReads.R/preprocessReadsChunk: Starting trimTailsByQuality ...
2024-06-13 00:12:35.08651 INFO::preprocessReads.R/preprocessReadsChunk: done
 done successfully.



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



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



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



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



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



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



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



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



Executing test function test_zipUp  ...  done successfully.



Executing test function test.FastQStreamer.getReads.pefq  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:12:35.435004 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:12:35.43744 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



Executing test function test.FastQStreamer.getReads.pefq.subsample  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:12:35.603769 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:12:35.702329 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-06-13 00:12:35.704989 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:12:35.707091 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



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



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



Executing test function test.FastQStreamer.subsampler.isdeterministic  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:12:36.249504 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:12:36.321794 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-06-13 00:12:36.324266 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:12:36.326419 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:12:36.551866 INFO::io.R/FastQStreamer.init: counting number of reads in file= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:12:36.599565 INFO::io.R/FastQStreamer.init: subsampling_filter set (subsampled reads= 17 , totnbreads= 26 )
2024-06-13 00:12:36.602079 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:12:36.604358 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
 done successfully.



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



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



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



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



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



Executing test function test.mergeLanes  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:12:37.333298 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-13 00:12:37.339082 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:12:37.342655 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-13 00:12:37.344984 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:12:40.46445 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:12:40.465983 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/chunks/chunk_000001/logs/progress.log
2024-06-13 00:12:43.124434 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.044 minutes
2024-06-13 00:12:43.126239 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/chunks/chunk_000002/logs/progress.log
2024-06-13 00:12:45.725556 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.043 minutes
2024-06-13 00:12:45.727178 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/chunks/chunk_000003/logs/progress.log
2024-06-13 00:12:48.321439 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.043 minutes
2024-06-13 00:12:48.371918 DEBUG::tools.R/processChunks: done
2024-06-13 00:12:48.375412 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-13 00:12:48.37733 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.adapter_contaminated_1.RData
2024-06-13 00:12:48.379535 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-13 00:12:48.381214 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.adapter_contaminated_2.RData
2024-06-13 00:12:48.389879 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-13 00:12:48.391683 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.summary_preprocess.tab
2024-06-13 00:12:48.394113 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/bams/processed.aligner_input_1.fastq ...
2024-06-13 00:12:48.397874 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/bams/processed.aligner_input_2.fastq ...
2024-06-13 00:12:48.400822 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/reports/shortReadReport_1 ...
2024-06-13 00:12:49.689692 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/reports/shortReadReport_2 ...
2024-06-13 00:12:50.701407 INFO::preprocessReads.R/preprocessReads: done
2024-06-13 00:12:50.77651 INFO::alignReads.R/alignReads: starting alignment...
2024-06-13 00:12:50.781333 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:12:53.814359 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:12:53.816097 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/chunks/chunk_000001/logs/progress.log
2024-06-13 00:12:56.379538 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.043 minutes
2024-06-13 00:12:56.381246 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/chunks/chunk_000002/logs/progress.log
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-06-13 00:12:59.007599 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.044 minutes
2024-06-13 00:12:59.009671 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/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-13 00:13:01.652551 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.044 minutes
2024-06-13 00:13:01.655724 DEBUG::tools.R/processChunks: done
2024-06-13 00:13:01.657526 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "T" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-06-13 00:13:01.845453 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-06-13 00:13:01.853345 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.summary_alignment.tab
2024-06-13 00:13:01.860013 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.summary_analyzed_bamstats.tab
2024-06-13 00:13:01.861839 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-06-13 00:13:02.086731 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.summary_target_lengths.tab
2024-06-13 00:13:02.133946 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-06-13 00:13:02.135148 INFO::alignReads.R/alignReads: done
2024-06-13 00:13:02.235217 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-06-13 00:13:02.254117 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:13:05.329537 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:13:05.331269 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/chunks/chunk_000001/logs/progress.log
2024-06-13 00:13:07.82849 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.042 minutes
2024-06-13 00:13:07.830708 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/chunks/chunk_000002/logs/progress.log
2024-06-13 00:13:10.278734 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.041 minutes
2024-06-13 00:13:10.280632 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/chunks/chunk_000003/logs/progress.log
2024-06-13 00:13:12.746568 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.041 minutes
2024-06-13 00:13:12.748992 DEBUG::tools.R/processChunks: done
2024-06-13 00:13:12.750859 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-06-13 00:13:12.765009 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.counts_exon.tab
2024-06-13 00:13:12.776536 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.counts_exon_disjoint.tab
2024-06-13 00:13:12.783799 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.counts_gene.tab
2024-06-13 00:13:12.78883 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.counts_gene_coding.tab
2024-06-13 00:13:12.793753 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.counts_gene_exonic.tab
2024-06-13 00:13:12.798774 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.counts_intergenic.tab
2024-06-13 00:13:12.807869 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.counts_intron.tab
2024-06-13 00:13:12.811127 INFO::countGenomicFeatures.R/mergeCounts: done
2024-06-13 00:13:12.816573 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.summary_counts.tab
2024-06-13 00:13:12.818203 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-06-13 00:13:13.111703 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-06-13 00:13:13.112756 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-06-13 00:13:13.221173 INFO::coverage.R/calculateCoverage: starting...
2024-06-13 00:13:13.226684 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:13:16.343393 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:13:16.345111 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/chunks/chunk_000001/logs/progress.log
2024-06-13 00:13:18.49368 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.036 minutes
2024-06-13 00:13:18.495226 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/chunks/chunk_000002/logs/progress.log
2024-06-13 00:13:20.6523 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.036 minutes
2024-06-13 00:13:20.654004 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/chunks/chunk_000003/logs/progress.log
2024-06-13 00:13:22.823993 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.036 minutes
2024-06-13 00:13:22.827686 DEBUG::tools.R/processChunks: done
2024-06-13 00:13:24.433899 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.coverage.RData
2024-06-13 00:13:24.436041 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.coverage.bw
2024-06-13 00:13:24.448288 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.summary_coverage.tab
2024-06-13 00:13:24.44975 INFO::coverage.R/calculateCoverage: done
2024-06-13 00:13:24.452218 INFO::analyzeVariants/analyzeVariants: starting ...
2024-06-13 00:13:24.551871 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-13 00:13:27.790164 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-13 00:13:27.858829 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-13 00:13:27.874112 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-13 00:13:27.875546 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.raw_variants.RData
2024-06-13 00:13:27.877062 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.filtered_variants.RData
2024-06-13 00:13:27.878274 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-13 00:13:27.879229 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-13 00:13:28.083274 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-13 00:13:28.18236 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/results/test_pe.summary_variants.tab
2024-06-13 00:13:28.1845 INFO::analyzeVariants/analyzeVariants: done
2024-06-13 00:13:28.188606 INFO::Pipeline run successful.
2024-06-13 00:13:28.363663 INFO::mergeLanes.R/doMergeLanes: starting...
2024-06-13 00:13:28.369433 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-13 00:13:28.371909 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.adapter_contaminated_1.RData
2024-06-13 00:13:28.375127 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-13 00:13:28.377123 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.adapter_contaminated_2.RData
2024-06-13 00:13:28.389867 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-13 00:13:28.392417 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.summary_preprocess.tab
2024-06-13 00:13:28.394882 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
[bam_translate] PG tag "A" on read "highqualAdapterContamIn3PrimeEnd:1:1:1:7#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInManyTxsOfMultiTxGene:1:1:1:16#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1MicrobialPE2MultimappingIntergenic:1:1:1:19#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1GeneFusionMidExonDiffChrPE2MultimappingIntergenic:1:1:1:25#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "T" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPE1UniqueUtrPE2MultimappingIntergenic:1:1:1:18#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
[bam_translate] PG tag "A" on read "highqualPEsInOneTxOfMultiTxGene:1:1:1:15#0" encountered with no corresponding entry in header, tag lost. Unknown tags are only reported once per input file for each tag ID.
2024-06-13 00:13:28.648535 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-06-13 00:13:28.656037 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.summary_alignment.tab
2024-06-13 00:13:28.664191 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.summary_analyzed_bamstats.tab
2024-06-13 00:13:28.666455 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-06-13 00:13:28.918522 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.summary_target_lengths.tab
2024-06-13 00:13:28.972398 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-06-13 00:13:29.020807 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-06-13 00:13:29.044509 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.counts_exon.tab
2024-06-13 00:13:29.057992 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.counts_exon_disjoint.tab
2024-06-13 00:13:29.065902 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.counts_gene.tab
2024-06-13 00:13:29.071809 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.counts_gene_coding.tab
2024-06-13 00:13:29.077541 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.counts_gene_exonic.tab
2024-06-13 00:13:29.083751 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.counts_intergenic.tab
2024-06-13 00:13:29.096244 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.counts_intron.tab
2024-06-13 00:13:29.09977 INFO::countGenomicFeatures.R/mergeCounts: done
2024-06-13 00:13:29.106267 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.summary_counts.tab
2024-06-13 00:13:29.108199 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-06-13 00:13:29.327404 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-06-13 00:13:31.300482 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.coverage.RData
2024-06-13 00:13:31.303253 INFO::coverage.R/saveCoverage: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.coverage.bw
2024-06-13 00:13:31.314432 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.summary_coverage.tab
2024-06-13 00:13:31.346239 INFO::analyzeVariants/analyzeVariants: starting ...
2024-06-13 00:13:31.43802 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-13 00:13:34.880553 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-13 00:13:34.959472 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-13 00:13:34.977414 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-13 00:13:34.978997 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.raw_variants.RData
2024-06-13 00:13:34.980717 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.filtered_variants.RData
2024-06-13 00:13:34.982089 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-13 00:13:34.983215 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-13 00:13:35.217963 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-13 00:13:35.323815 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.mergeLanes.30d29e4cbd22c4/merged/results/merged.summary_variants.tab
2024-06-13 00:13:35.326024 INFO::analyzeVariants/analyzeVariants: done
2024-06-13 00:13:35.329226 INFO::mergeLanes.R/doMergeLanes: merge lanes successful.
 done successfully.



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



Executing test function test.markDuplicates_w_outfile  ... Timing stopped at: 0 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/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:13:35.675085 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-13 00:13:35.700639 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:13:35.725501 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-13 00:13:35.728986 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:13:44.890298 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:13:44.893972 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpMMnlZB/test.preprocessReads.30d29e7c0aaeaa/chunks/chunk_000001/logs/progress.log
2024-06-13 00:13:48.659246 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.063 minutes
2024-06-13 00:13:48.983313 DEBUG::tools.R/processChunks: done
2024-06-13 00:13:48.988704 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-13 00:13:48.991987 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.preprocessReads.30d29e7c0aaeaa/results/test_pe.adapter_contaminated_1.RData
2024-06-13 00:13:49.020066 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-13 00:13:49.023957 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.preprocessReads.30d29e7c0aaeaa/results/test_pe.adapter_contaminated_2.RData
2024-06-13 00:13:49.054986 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-13 00:13:49.059194 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.preprocessReads.30d29e7c0aaeaa/results/test_pe.summary_preprocess.tab
2024-06-13 00:13:49.063493 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpMMnlZB/test.preprocessReads.30d29e7c0aaeaa/bams/processed.aligner_input_1.fastq ...
2024-06-13 00:13:49.089706 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpMMnlZB/test.preprocessReads.30d29e7c0aaeaa/bams/processed.aligner_input_2.fastq ...
2024-06-13 00:13:49.117267 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpMMnlZB/test.preprocessReads.30d29e7c0aaeaa/reports/shortReadReport_1 ...
2024-06-13 00:13:52.703673 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpMMnlZB/test.preprocessReads.30d29e7c0aaeaa/reports/shortReadReport_2 ...
2024-06-13 00:13:54.954777 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads.minichunks  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:13:55.723603 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-13 00:13:55.73669 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:13:55.74533 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_2.fastq
2024-06-13 00:13:55.750758 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:14:00.801518 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:14:00.803029 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpMMnlZB/test.preprocessReads.minichunks.30d29e21f21243/chunks/chunk_000001/logs/progress.log
2024-06-13 00:14:03.84127 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.051 minutes
2024-06-13 00:14:03.845002 DEBUG::tools.R/processChunks: starting chunkid= 2 ; see logfile= /tmp/RtmpMMnlZB/test.preprocessReads.minichunks.30d29e21f21243/chunks/chunk_000002/logs/progress.log
2024-06-13 00:14:07.124042 DEBUG::tools.R/processChunks: done with chunkid= 2 ; elapsed.time= 0.055 minutes
2024-06-13 00:14:07.129488 DEBUG::tools.R/processChunks: starting chunkid= 3 ; see logfile= /tmp/RtmpMMnlZB/test.preprocessReads.minichunks.30d29e21f21243/chunks/chunk_000003/logs/progress.log
2024-06-13 00:14:10.385644 DEBUG::tools.R/processChunks: done with chunkid= 3 ; elapsed.time= 0.054 minutes
2024-06-13 00:14:10.578806 DEBUG::tools.R/processChunks: done
2024-06-13 00:14:10.586973 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-13 00:14:10.590976 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.preprocessReads.minichunks.30d29e21f21243/results/test_pe.adapter_contaminated_1.RData
2024-06-13 00:14:10.596326 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-13 00:14:10.60051 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.preprocessReads.minichunks.30d29e21f21243/results/test_pe.adapter_contaminated_2.RData
2024-06-13 00:14:10.623021 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-13 00:14:10.627302 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.preprocessReads.minichunks.30d29e21f21243/results/test_pe.summary_preprocess.tab
2024-06-13 00:14:10.633226 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpMMnlZB/test.preprocessReads.minichunks.30d29e21f21243/bams/processed.aligner_input_1.fastq ...
2024-06-13 00:14:10.643842 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpMMnlZB/test.preprocessReads.minichunks.30d29e21f21243/bams/processed.aligner_input_2.fastq ...
2024-06-13 00:14:10.652338 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpMMnlZB/test.preprocessReads.minichunks.30d29e21f21243/reports/shortReadReport_1 ...
2024-06-13 00:14:13.72816 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpMMnlZB/test.preprocessReads.minichunks.30d29e21f21243/reports/shortReadReport_2 ...
2024-06-13 00:14:15.2838 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



Executing test function test.preprocessReads_single_end  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:14:15.798737 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-13 00:14:15.828497 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/test-data/unit_tests_1.fastq
2024-06-13 00:14:15.832754 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:14:20.859046 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:14:20.86112 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= /tmp/RtmpMMnlZB/test.preprocessReads_single_end.30d29e717c0e84/chunks/chunk_000001/logs/progress.log
2024-06-13 00:14:23.335766 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.041 minutes
2024-06-13 00:14:23.350685 DEBUG::tools.R/processChunks: done
2024-06-13 00:14:23.354455 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-13 00:14:23.356663 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.preprocessReads_single_end.30d29e717c0e84/results/test_se.adapter_contaminated_1.RData
2024-06-13 00:14:23.366823 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-13 00:14:23.369549 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.preprocessReads_single_end.30d29e717c0e84/results/test_se.summary_preprocess.tab
2024-06-13 00:14:23.372731 INFO::preprocessReads.R/mergePreprocessedReads: merging file= /tmp/RtmpMMnlZB/test.preprocessReads_single_end.30d29e717c0e84/bams/processed.aligner_input_1.fastq ...
2024-06-13 00:14:23.377608 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= /tmp/RtmpMMnlZB/test.preprocessReads_single_end.30d29e717c0e84/reports/shortReadReport_1 ...
2024-06-13 00:14:24.941895 INFO::preprocessReads.R/preprocessReads: done
 done successfully.



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



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



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



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



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



Executing test function test.runPipeline  ... checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:14:25.692693 INFO::preprocessReads.R/preprocessReads: starting...
2024-06-13 00:14:25.731358 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_1.fastq.gz
2024-06-13 00:14:25.767877 INFO::io.R/FastQStreamer.init: initialised FastQ streamer for filename= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/extdata/H1993_TP53_subset2500_2.fastq.gz
2024-06-13 00:14:25.771056 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:14:29.309192 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:14:29.310688 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-06-13 00:14:32.124302 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.047 minutes
2024-06-13 00:14:32.169842 DEBUG::tools.R/processChunks: done
2024-06-13 00:14:32.172411 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_1 ...
2024-06-13 00:14:32.174022 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_1.RData
2024-06-13 00:14:32.175971 INFO::detectAdapterContam.R/mergeDetectAdapterContam: merging file= adapter_contaminated_2 ...
2024-06-13 00:14:32.177391 INFO::io.R/saveWithID: saving file= test/results/test.adapter_contaminated_2.RData
2024-06-13 00:14:32.184205 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-13 00:14:32.18604 INFO::io.R/saveWithID: saving file= test/results/test.summary_preprocess.tab
2024-06-13 00:14:32.188017 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_1.fastq ...
2024-06-13 00:14:32.193951 INFO::preprocessReads.R/mergePreprocessedReads: merging file= test/bams/processed.aligner_input_2.fastq ...
2024-06-13 00:14:32.197787 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_1 ...
2024-06-13 00:14:33.896188 INFO::preprocessReads.R/buildShortReadReports: generating report_dir= test/reports/shortReadReport_2 ...
2024-06-13 00:14:35.090128 INFO::preprocessReads.R/preprocessReads: done
2024-06-13 00:14:35.187301 INFO::alignReads.R/alignReads: starting alignment...
2024-06-13 00:14:35.192941 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:14:38.089709 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:14:38.091389 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-13 00:14:42.632759 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.076 minutes
2024-06-13 00:14:42.640097 DEBUG::tools.R/processChunks: done
2024-06-13 00:14:42.642418 INFO::alignReads.R/mergeBAMsAcrossDirs: starting...
2024-06-13 00:14:42.677191 INFO::alignReads.R/mergeBAMsAcrossDirs: done
2024-06-13 00:14:42.684364 INFO::io.R/saveWithID: saving file= test/results/test.summary_alignment.tab
2024-06-13 00:14:42.689697 INFO::io.R/saveWithID: saving file= test/results/test.summary_analyzed_bamstats.tab
2024-06-13 00:14:42.69172 INFO::reportPipelineQA.R/writePreprocessAlignReport: creating joint preprocess-alignment report...
2024-06-13 00:14:42.848799 INFO::io.R/saveWithID: saving file= test/results/test.summary_target_lengths.tab
2024-06-13 00:14:42.896977 INFO::reportPipelineQA.R/writePreprocessAlignReport: done
2024-06-13 00:14:42.89815 INFO::alignReads.R/alignReads: done
2024-06-13 00:14:42.990774 INFO::countGenomicFeatures.R/countGenomicFeatures: starting...
2024-06-13 00:14:43.016705 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:14:47.162019 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:14:47.163985 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-06-13 00:14:49.663421 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.042 minutes
2024-06-13 00:14:49.665859 DEBUG::tools.R/processChunks: done
2024-06-13 00:14:49.667506 INFO::countGenomicFeatures.R/mergeCounts: starting...
2024-06-13 00:14:49.677507 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon.tab
2024-06-13 00:14:49.687569 INFO::io.R/saveWithID: saving file= test/results/test.counts_exon_disjoint.tab
2024-06-13 00:14:49.694458 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene.tab
2024-06-13 00:14:49.698608 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_coding.tab
2024-06-13 00:14:49.702545 INFO::io.R/saveWithID: saving file= test/results/test.counts_gene_exonic.tab
2024-06-13 00:14:49.7066 INFO::io.R/saveWithID: saving file= test/results/test.counts_intergenic.tab
2024-06-13 00:14:49.713373 INFO::io.R/saveWithID: saving file= test/results/test.counts_intron.tab
2024-06-13 00:14:49.717174 INFO::countGenomicFeatures.R/mergeCounts: done
2024-06-13 00:14:49.720632 INFO::io.R/saveWithID: saving file= test/results/test.summary_counts.tab
2024-06-13 00:14:49.722373 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: creating report of genomic features counts...
2024-06-13 00:14:49.939883 INFO::reportPipelineQA.R/writeGenomicFeaturesReport: done
2024-06-13 00:14:49.940865 INFO::countGenomicFeatures.R/countGenomicFeatures: done...
2024-06-13 00:14:50.02588 INFO::coverage.R/calculateCoverage: starting...
2024-06-13 00:14:50.031002 DEBUG::tools.R/processChunks: starting...
2024-06-13 00:14:52.981583 DEBUG::tools.R/processChunks: waiting for chunkid=[  ] ...
2024-06-13 00:14:52.983381 DEBUG::tools.R/processChunks: starting chunkid= 1 ; see logfile= test/chunks/chunk_000001/logs/progress.log
2024-06-13 00:14:55.323479 DEBUG::tools.R/processChunks: done with chunkid= 1 ; elapsed.time= 0.039 minutes
2024-06-13 00:14:55.32598 DEBUG::tools.R/processChunks: done
2024-06-13 00:14:56.881144 INFO::io.R/saveWithID: saving file= test/results/test.coverage.RData
2024-06-13 00:14:56.882978 INFO::coverage.R/saveCoverage: saving file= test/results/test.coverage.bw
2024-06-13 00:14:56.961967 INFO::io.R/saveWithID: saving file= test/results/test.summary_coverage.tab
2024-06-13 00:14:56.963433 INFO::coverage.R/calculateCoverage: done
2024-06-13 00:14:56.964736 INFO::analyzeVariants/analyzeVariants: starting ...
2024-06-13 00:14:57.045098 INFO::analyzeVariants.R/wrap.callVariants: Tallying variants...
2024-06-13 00:15:07.652006 INFO::analyzeVariants.R/wrap.callVariants: calling variants...
2024-06-13 00:15:07.719906 INFO::analyzeVariants.R/wrap.postFilerVariants: post filtering variants...
2024-06-13 00:15:07.734771 INFO::analyzeVariants.R/wrap.callVariants: Saving GRanges of raw and filtered variants...
2024-06-13 00:15:07.736026 INFO::io.R/saveWithID: saving file= test/results/test.raw_variants.RData
2024-06-13 00:15:07.73867 INFO::io.R/saveWithID: saving file= test/results/test.filtered_variants.RData
2024-06-13 00:15:07.73996 INFO::analyzeVariants.R/wrap.callVariants: ...done
2024-06-13 00:15:07.740893 INFO::analyzeVariants.R/writeVCF: writing vcf file...
2024-06-13 00:15:07.938113 INFO::analyzeVariants.R/writeVCF: ...done
2024-06-13 00:15:08.030453 INFO::io.R/saveWithID: saving file= test/results/test.summary_variants.tab
2024-06-13 00:15:08.032671 INFO::analyzeVariants/analyzeVariants: done
2024-06-13 00:15:08.041561 INFO::Pipeline run successful.
 done successfully.



Executing test function test.calculateTargetLength  ... checkConfig.R/checkConfig.template: loading template config= //tmp/RtmpMMnlZB/tp53-config.txt 
checkConfig.R/checkConfig.template: loading template config= /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/config/default-config.txt 
2024-06-13 00:15:08.282856 INFO::io.R/saveWithID: saving file= /tmp/RtmpMMnlZB/test.calcTargetLengths.30d29e6f442e5f/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 -- Thu Jun 13 00:15:21 2024 
*********************************************** 
Number of test functions: 61 
Number of deactivated test functions: 10 
Number of errors: 0 
Number of failures: 0 

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



Details 
*************************** 
Test Suite: HTSeqGenie unit testing 
Test function regexp: ^test.+ 
Test file regexp: ^runit.+\.[rR]$ 
Involved directory: 
/home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests 
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.alignReads.R 
test.alignReads: (2 checks) ... OK (27.48 seconds)
test.alignReads.sparsechunks: (2 checks) ... OK (16.6 seconds)
test.alignReadsOneSingleEnd: (2 checks) ... OK (0.5 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.analyzeVariants.R 
test.annotateVariants : DEACTIVATED, Skipped annotateVariants() test
test.callVariantsVariantTools.genotype: (2 checks) ... OK (68.73 seconds)
test.wrap.callVariants: (4 checks) ... OK (10.85 seconds)
test.wrap.callVariants.filters: (2 checks) ... OK (20.83 seconds)
test.wrap.callVariants.which: (1 checks) ... OK (3.16 seconds)
test.writeVCF.NULL: (1 checks) ... OK (0.14 seconds)
test.writeVCF.vcfStat: (4 checks) ... OK (2.06 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.bamUtils.R 
test.isFirstFragment: (5 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.buildGenomicFeatures.R 
test.buildCountsGRangesList: (3 checks) ... OK (26.62 seconds)
test.generateSingleGeneDERs: (4 checks) ... OK (23.74 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.calculateCoverage.R 
test.computeCoverage: (9 checks) ... OK (0.63 seconds)
test.isSparse: (5 checks) ... OK (0.1 seconds)
test.mergeCoverage: (1 checks) ... OK (1.51 seconds)
test.mergeCoverage.sparse: (2 checks) ... OK (1.25 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.checkConfig.R 
test.checkConfig.analyzeVariants: (5 checks) ... OK (0.15 seconds)
test.findTemplate: (5 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.config.R 
test.checkConfig: (5 checks) ... OK (0.32 seconds)
test.checkConfig.alignReads: (5 checks) ... OK (0.38 seconds)
test.getConfig: (14 checks) ... OK (0 seconds)
test.loadConfig: (2 checks) ... OK (0 seconds)
test.parseDCF: (7 checks) ... OK (0 seconds)
test.updateConfig: (1 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.detectAdapterContam.R 
test.getAdapterSeqs: (5 checks) ... OK (0.04 seconds)
test.isAdapter: (5 checks) ... OK (0.11 seconds)
test.isAdapter3.primeEnd: (1 checks) ... OK (0.08 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.detectRRNA.R 
test.detectRRNA: (1 checks) ... OK (0.42 seconds)
test.detectRRNA.paired_end: (1 checks) ... OK (0.43 seconds)
test.getRRNAIds: (1 checks) ... OK (0.31 seconds)
test.getRRNAIds_random: (1 checks) ... OK (0.26 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.filterQuality.R 
test.filterByLength: (2 checks) ... OK (0.06 seconds)
test.isAboveQualityThresh: (3 checks) ... OK (0.05 seconds)
test.trimTailsByQuality: (4 checks) ... OK (0.04 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.gatk.R 
test.callVariantsGATK : DEACTIVATED, callVariantsGATK() tests need gatk.path option set
test.callVariantsGATK.withFiltering : DEACTIVATED, callVariantsGATK() tests need gatk.path option set
test.checkGATKJar : DEACTIVATED, checkGATKJar() test needs gatk.path option set
test.excludeVariantsByRegion: (3 checks) ... OK (0.16 seconds)
test.gatk : DEACTIVATED, gatk() tests need gatk.path option set
test.realignIndels : DEACTIVATED, test.realignIndels() tests need gatk.path option set
test.realignIndelsGATK : DEACTIVATED, realignIndelsGATK() tests need gatk.path option set
test.realignIndelsGATK.parallel : DEACTIVATED, realignIndelsGATK() tests need gatk.path option set
test_zipUp: (3 checks) ... OK (0 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.io.R 
test.FastQStreamer.getReads.pefq: (1 checks) ... OK (0.22 seconds)
test.FastQStreamer.getReads.pefq.subsample: (1 checks) ... OK (0.31 seconds)
test.FastQStreamer.getReads.segz: (1 checks) ... OK (0.15 seconds)
test.FastQStreamer.getReads.truncated: (1 checks) ... OK (0.18 seconds)
test.FastQStreamer.subsampler.isdeterministic: (3 checks) ... OK (0.57 seconds)
test.createTmpDir: (4 checks) ... OK (0 seconds)
test.detectQualityInFASTQFile: (3 checks) ... OK (0.14 seconds)
test.getObjectFilename: (4 checks) ... OK (0 seconds)
test.safeUnlink: (2 checks) ... OK (0 seconds)
test.writeAudit: (0 checks) ... OK (0.17 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.mergeLanes.R 
test.mergeLanes: (6 checks) ... OK (58.34 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.picard.R 
test.markDuplicates : DEACTIVATED, Skipped markDuplicates() test
test.markDuplicates_w_outfile : DEACTIVATED, Skipped markDuplicates() test
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.preprocessReads.R 
test.preprocessReads: (5 checks) ... OK (19.6 seconds)
test.preprocessReads.minichunks: (5 checks) ... OK (20.33 seconds)
test.preprocessReads_single_end: (5 checks) ... OK (9.65 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.readRNASeqEnds.R 
test.readRNASeqEnds: (6 checks) ... OK (0.15 seconds)
test.readRNASeqEnds.dupmark: (2 checks) ... OK (0.11 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.reportPipelineQA.R 
test.how_many: (3 checks) ... OK (0 seconds)
test.plotDF: (3 checks) ... OK (0.16 seconds)
test.relativeBarPlot: (2 checks) ... OK (0.05 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.runPipeline.R 
test.runPipeline: (1 checks) ... OK (42.62 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.targetLengths.R 
test.calculateTargetLength: (4 checks) ... OK (0.24 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.tools.R 
test.sclapply: (10 checks) ... OK (13.18 seconds)
test.tryKeepTraceback: (3 checks) ... OK (0.01 seconds)
--------------------------- 
Test file: /home/biocbuild/bbs-3.19-bioc/R/site-library/HTSeqGenie/unitTests/runit.trimReads.R 
test.truncateReads: (7 checks) ... OK (0.05 seconds)
test.truncateReads.trim5: (15 checks) ... OK (0.14 seconds) 

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

Example timings

HTSeqGenie.Rcheck/HTSeqGenie-Ex.timings

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