ATACorrect: raise pickle.PicklingError('logger cannot be pickled')

[ro-zeta]

Hello,

I am trying to use the test data provided to see if I can reproduce the data from the publication with python 3.8.8. I cannot run any of the commands. For all commands in the framework I get an error saying: "raise pickle.PicklingError('logger cannot be pickled')". Please see below for an example:

(base) comp:~ user$ TOBIAS FootprintScores --signal test_data/Bcell_corrected.bw --regions test_data/merged_peaks.bed --output Bcell_footprints.bw --cores 2
'# TOBIAS 0.13.2 ScoreBigwig (run started 2022-03-27 23:02:56.064916)
'# Working directory: /Users/user
'# Command line call: TOBIAS FootprintScores --signal test_data/Bcell_corrected.bw --regions test_data/merged_peaks.bed --output Bcell_footprints.bw --cores 2

'# ----- Input parameters -----
'# signal: test_data/Bcell_corrected.bw
'# output: Bcell_footprints.bw
'# regions: test_data/merged_peaks.bed
'# score: footprint
'# absolute: False
'# extend: 100
'# smooth: 1
'# min_limit: None
'# max_limit: None
'# fp_min: 20
'# fp_max: 50
'# flank_min: 10
'# flank_max: 30
'# window: 100
'# cores: 2
'# split: 100
'# verbosity: 3

'# ----- Output files -----
'# Bcell_footprints.bw

Traceback (most recent call last):
File "/opt/anaconda3/bin/TOBIAS", line 8, in
sys.exit(main())
File "/opt/anaconda3/lib/python3.8/site-packages/tobias/TOBIAS.py", line 154, in main
args.func(args)
File "/opt/anaconda3/lib/python3.8/site-packages/tobias/tools/score_bigwig.py", line 120, in run_scorebigwig
logger.start_logger_queue()
File "/opt/anaconda3/lib/python3.8/site-packages/tobias/utils/logger.py", line 130, in start_logger_queue
self.listener.start()
File "/opt/anaconda3/lib/python3.8/multiprocessing/process.py", line 121, in start
self._popen = self._Popen(self)
File "/opt/anaconda3/lib/python3.8/multiprocessing/context.py", line 224, in _Popen
return _default_context.get_context().Process._Popen(process_obj)
File "/opt/anaconda3/lib/python3.8/multiprocessing/context.py", line 284, in _Popen
return Popen(process_obj)
File "/opt/anaconda3/lib/python3.8/multiprocessing/popen_spawn_posix.py", line 32, in init
super().init(process_obj)
File "/opt/anaconda3/lib/python3.8/multiprocessing/popen_fork.py", line 19, in init
self._launch(process_obj)
File "/opt/anaconda3/lib/python3.8/multiprocessing/popen_spawn_posix.py", line 47, in _launch
reduction.dump(process_obj, fp)
File "/opt/anaconda3/lib/python3.8/multiprocessing/reduction.py", line 60, in dump
ForkingPickler(file, protocol).dump(obj)
File "/opt/anaconda3/lib/python3.8/logging/init.py", line 1735, in reduce
raise pickle.PicklingError('logger cannot be pickled')
_pickle.PicklingError: logger cannot be pickled

[msbentsen]

Hi @ro-zeta,

Sorry about this error - can you provide a little more information about the system you are on? Maybe Mac? I have another issue on the UROPA software (we manage both tools in the lab) at loosolab/UROPA#13, which seems to be the same.

If you could provide me with the output of pip freeze that would be great - then I can correlate it with the other issue, thank you!

[njrobins]

Hi @ro-zeta! I am also having a similar issue with both TOBIAS and UROPA, as Mette alluded to, and I wanted to draw your attention back to her question. Hopefully, armed with the information she has requested, she can compare our systems/dependencies to identify something that may be underlying our shared problem. Thanks so much!

[imran-aifi]

I also encountered this issue - only when running on my local Mac (Monterey 12.2.1) with Python 3.10.4, and not on a HPC with Linux and Python 3.7.12.

On my Mac with the issue, here's the pip freeze output:

$ pip freeze
autopep8==1.6.0
pyBigWig==0.3.18
pycodestyle==2.8.0
PyPDF2==1.26.0
pysam==0.19.0
pytz==2022.1
six @ file:///AppleInternal/BuildRoot/Library/Caches/com.apple.xbs/Sources/python3/python3-110/six-1.15.0-py2.py3-none-any.whl
toml==0.10.2
Wand==0.6.7

$ pip3 freeze
pyBigWig==0.3.18
PyPDF2==1.26.0
pysam==0.19.0
pytz==2022.1
Wand==0.6.7

[sneddonucsf]

Hello,

I am also encountering this issue on macOS Catalina v. 10.15.7

TOBIAS ATACorrect --read_shift 0 0 --bam /Users/seandelao/Desktop/IReNA_v2_Analysis/Bed_files/Acinar_fragments_cl_bamGR_pe_s.bam --genome /Users/seandelao/Desktop/IReNA_v2_Analysis/supplement/mm10.fa --peaks /Users/seandelao/Desktop/IReNA_v2_Analysis/supplement/Endocrine_peaks.bed --blacklist /Users/seandelao/Desktop/IReNA_v2_Analysis/supplement/mm10-blacklist.v2.bed --outdir /Users/seandelao/Desktop/IReNA_v2_Analysis/TOBIAS_output/Acinar --cores 4

returns:

# TOBIAS 0.13.3 ATACorrect (run started 2022-04-04 23:29:54.312922)
# Working directory: /Users/seandelao
# Command line call: TOBIAS ATACorrect --read_shift 0 0 --bam /Users/seandelao/Desktop/IReNA_v2_Analysis/Bed_files/Acinar_fragments_cl_bamGR_pe_s.bam --genome /Users/seandelao/Desktop/IReNA_v2_Analysis/supplement/mm10.fa --peaks /Users/seandelao/Desktop/IReNA_v2_Analysis/supplement/Endocrine_peaks.bed --blacklist /Users/seandelao/Desktop/IReNA_v2_Analysis/supplement/mm10-blacklist.v2.bed --outdir /Users/seandelao/Desktop/IReNA_v2_Analysis/TOBIAS_output/Acinar --cores 4

# ----- Input parameters -----
# bam:	/Users/seandelao/Desktop/IReNA_v2_Analysis/Bed_files/Acinar_fragments_cl_bamGR_pe_s.bam
# genome:	/Users/seandelao/Desktop/IReNA_v2_Analysis/supplement/mm10.fa
# peaks:	/Users/seandelao/Desktop/IReNA_v2_Analysis/supplement/Endocrine_peaks.bed
# regions_in:	None
# regions_out:	None
# blacklist:	/Users/seandelao/Desktop/IReNA_v2_Analysis/supplement/mm10-blacklist.v2.bed
# extend:	100
# split_strands:	False
# norm_off:	False
# track_off:	[]
# k_flank:	12
# read_shift:	[0, 0]
# bg_shift:	100
# window:	100
# score_mat:	DWM
# prefix:	Acinar_fragments_cl_bamGR_pe_s
# outdir:	/Users/seandelao/Desktop/IReNA_v2_Analysis/TOBIAS_output/Acinar
# cores:	4
# split:	100
# verbosity:	3


# ----- Output files -----
# /Users/seandelao/Desktop/IReNA_v2_Analysis/TOBIAS_output/Acinar/Acinar_fragments_cl_bamGR_pe_s_uncorrected.bw
# /Users/seandelao/Desktop/IReNA_v2_Analysis/TOBIAS_output/Acinar/Acinar_fragments_cl_bamGR_pe_s_bias.bw
# /Users/seandelao/Desktop/IReNA_v2_Analysis/TOBIAS_output/Acinar/Acinar_fragments_cl_bamGR_pe_s_expected.bw
# /Users/seandelao/Desktop/IReNA_v2_Analysis/TOBIAS_output/Acinar/Acinar_fragments_cl_bamGR_pe_s_corrected.bw
# /Users/seandelao/Desktop/IReNA_v2_Analysis/TOBIAS_output/Acinar/Acinar_fragments_cl_bamGR_pe_s_atacorrect.pdf


2022-04-04 23:29:54 (74923) [INFO]	----- Processing input data -----
2022-04-04 23:29:54 (74923) [INFO]	Reading info from .bam file
2022-04-04 23:29:54 (74923) [INFO]	Reading info from .fasta file
2022-04-04 23:29:54 (74923) [INFO]	Processing input/output regions
2022-04-04 23:30:06 (74923) [STATS]	genome: 21 regions | 2725521370 bp | 100.00% coverage
2022-04-04 23:30:06 (74923) [STATS]	input_regions: 202658 regions | 2396135053 bp | 87.91% coverage
2022-04-04 23:30:06 (74923) [STATS]	output_regions: 141961 regions | 123804825 bp | 4.54% coverage
2022-04-04 23:30:06 (74923) [STATS]	peak_regions: 180842 regions | 90409117 bp | 3.32% coverage
2022-04-04 23:30:06 (74923) [STATS]	nonpeak_regions: 202658 regions | 2396135053 bp | 87.91% coverage
2022-04-04 23:30:06 (74923) [STATS]	blacklist_regions: 3435 regions | 238977200 bp | 8.77% coverage
Traceback (most recent call last):
  File "/Users/seandelao/opt/miniconda3/bin/TOBIAS", line 8, in <module>
    sys.exit(main())
  File "/Users/seandelao/opt/miniconda3/lib/python3.8/site-packages/tobias/TOBIAS.py", line 154, in main
    args.func(args)		
  File "/Users/seandelao/opt/miniconda3/lib/python3.8/site-packages/tobias/tools/atacorrect.py", line 261, in run_atacorrect
    logger.start_logger_queue()
  File "/Users/seandelao/opt/miniconda3/lib/python3.8/site-packages/tobias/utils/logger.py", line 130, in start_logger_queue
    self.listener.start()
  File "/Users/seandelao/opt/miniconda3/lib/python3.8/multiprocessing/process.py", line 121, in start
    self._popen = self._Popen(self)
  File "/Users/seandelao/opt/miniconda3/lib/python3.8/multiprocessing/context.py", line 224, in _Popen
    return _default_context.get_context().Process._Popen(process_obj)
  File "/Users/seandelao/opt/miniconda3/lib/python3.8/multiprocessing/context.py", line 284, in _Popen
    return Popen(process_obj)
  File "/Users/seandelao/opt/miniconda3/lib/python3.8/multiprocessing/popen_spawn_posix.py", line 32, in __init__
    super().__init__(process_obj)
  File "/Users/seandelao/opt/miniconda3/lib/python3.8/multiprocessing/popen_fork.py", line 19, in __init__
    self._launch(process_obj)
  File "/Users/seandelao/opt/miniconda3/lib/python3.8/multiprocessing/popen_spawn_posix.py", line 47, in _launch
    reduction.dump(process_obj, fp)
  File "/Users/seandelao/opt/miniconda3/lib/python3.8/multiprocessing/reduction.py", line 60, in dump
    ForkingPickler(file, protocol).dump(obj)
  File "/Users/seandelao/opt/miniconda3/lib/python3.8/logging/__init__.py", line 1727, in __reduce__
    raise pickle.PicklingError('logger cannot be pickled')
_pickle.PicklingError: logger cannot be pickled

[msbentsen]

Did it ever work for any of you, and then stopped working? Or was this the first time trying it out?

There were apparently some changes in the spawning of multiprocesses between MacOS and Unix for python 3.8: https://docs.python.org/3/library/multiprocessing.html#contexts-and-start-methods.

Can you try to downgrade to python 3.7 and see if this fixes the error? Otherwise I will also have a look a bit deeper to provide a fix for MacOS.

[sneddonucsf]

@msbentsen I downgraded to python 3.7 and it seems to be running smoothly now!

[njrobins]

Yes, I also downgraded to python 3.7 and was successful in running both UROPA and TOBIAS. Thank you!

[msbentsen]

Amazing, thank you very much for the feedback! So as reference for future issues: Due to changes in python's multiprocessing module, MacOS systems require python < 3.8 to run TOBIAS (and UROPA) tools. I will close this issue, but feel free to reopen should there still be problems.