`prot.xml` was written to the temp directory but not the result directory, which resulted in the incomplete file and crashed the filter command #429

ohickl · 2023-03-30T07:36:49Z

Hi,

I am running some tests on linux with a large database built from multiple metagenomes. It crashes at the filtering step with:

...
time="02:21:03" level=error msg="Cannot decode packed binary. XML syntax error on line 361982260: unexpected EOF"
panic: Cannot decode packed binary. XML syntax error on line 361982260: unexpected EOF

goroutine 1 [running]:
philosopher/lib/msg.callLogrus({0xcab9050320, 0x4f}, {0xb379d5, 0x1?})
        /workspace/philosopher/lib/msg/msg.go:319 +0x354
philosopher/lib/msg.DecodeMsgPck({0xca0640?, 0xc73993a168?}, {0xb379d5, 0x5})
        /workspace/philosopher/lib/msg/msg.go:120 +0x6e
philosopher/lib/spc.(*ProtXML).Parse(0xc002a55910, {0x7fffb4eaa687, 0x62})
        /workspace/philosopher/lib/spc/spc.go:97 +0x210
philosopher/lib/id.(*ProtXML).Read(0xc002a55bb8, {0x7fffb4eaa687?, 0xc0002b5b90?})
        /workspace/philosopher/lib/id/pro.go:116 +0x85
philosopher/lib/fil.ReadProtXMLInput({0x7fffb4eaa687?, 0xd?}, {0x7fffb4eaa617, 0x4}, 0x3ff0000000000000)
        /workspace/philosopher/lib/fil/fil.go:504 +0x9f
philosopher/lib/fil.Run({{0xc0000288a0, 0x24}, {0xc00002c8a0, 0x57}, {0xc0000288d0, 0x29}, {0xc0000fe3f0, 0x66}, {0xc00002c900, 0x5d}, ...})
        /workspace/philosopher/lib/fil/fil.go:81 +0x77a
philosopher/cmd.glob..func5(0x2610bc0?, {0xb3726a?, 0xa?, 0xa?})
        /workspace/philosopher/cmd/filter.go:43 +0x390
github.com/spf13/cobra.(*Command).execute(0x2610bc0, {0xc000286b40, 0xa, 0xa})
        /home/prvst/go/pkg/mod/github.com/spf13/[email protected]/command.go:920 +0x847
github.com/spf13/cobra.(*Command).ExecuteC(0x260f4c0)
        /home/prvst/go/pkg/mod/github.com/spf13/[email protected]/command.go:1044 +0x3bd
github.com/spf13/cobra.(*Command).Execute(...)
        /home/prvst/go/pkg/mod/github.com/spf13/[email protected]/command.go:968
philosopher/cmd.Execute()
        /workspace/philosopher/cmd/root.go:35 +0x25
main.main()
        /workspace/philosopher/main.go:25 +0x90
Process 'PhilosopherFilter' finished, exit code: 2
Process returned non-zero exit code, stopping

~~~~~~~~~~~~~~~~~~~~
Cancelling 5 remaining tasks

The command is:

${fragpipe_bin} --headless \
                --workflow ${fragpipe_dir}/workflows/LFQ-MBR_template.workflow \
                --manifest ${fragpipe_dir}/workflows/template.fp-manifest \
                --workdir ${db_dir}/sample_01_fragpipe_test_closed_all_samp_db_01 \
                --ram 1700 \
                --threads 60 \
                --config-msfragger ${msfragger_bin} \
                --config-ionquant ${ionquant_bin} \
                --config-philosopher ${phil_bin} \
                --config-python ${CONDA_PREFIX}/bin/python3.10 > sample_01_fragpipe_test_closed_all_samp_db_01.log 2>&1

I assume, this might be what @anesvi mentioned before: #427 (comment)?

Also, it never seemed to actually go much beyond the memory requirements reported per database slice for the fragments to be searched (e.g. ~120G). It did crash though, if I decreased the number of slices to e.g. 20 from 25. Is this because it hits the limit for the number of elements in the index? Ideally, I would like to have as few db slices as possible and use more of the available memory. I did not log the memory consumption though, so it might be that I just missed a large spike.

Best

Oskar

sample_01_fragpipe_test_closed_all_samp_db_01.log

The text was updated successfully, but these errors were encountered:

fcyu · 2023-03-30T13:05:59Z

Hi Oskar,

The database splits option is for MSFragger, which has finished successfully. The error you had was from Philosopher filter command. I will let Felipe @prvst to take a look.

Following is a "more complete" error message

time="01:22:05" level=info msg=Done
Process 'ProteinProphet' finished, exit code: 0
PhilosopherDbAnnotate [Work dir: .../sample_01_fragpipe_test_closed_all_samp_db_01]
.../philosopher/philosopher database --annotate .../all_sample_db/2023-03-29-decoys-mibipa_all_hs_crap_final_num_header.faa.fas --prefix rev_
time="01:22:05" level=info msg="Executing Database  v4.8.1"
time="01:22:05" level=info msg="Annotating the database"
time="01:40:17" level=info msg=Done
Process 'PhilosopherDbAnnotate' finished, exit code: 0
PhilosopherDbAnnotate [Work dir: .../sample_01_fragpipe_test_closed_all_samp_db_01/sample_01]
.../philosopher/philosopher database --annotate .../all_sample_db/2023-03-29-decoys-mibipa_all_hs_crap_final_num_header.faa.fas --prefix rev_
time="01:40:21" level=info msg="Executing Database  v4.8.1"
time="01:40:21" level=info msg="Annotating the database"
time="01:57:44" level=info msg=Done
Process 'PhilosopherDbAnnotate' finished, exit code: 0
PhilosopherFilter [Work dir: .../sample_01_fragpipe_test_closed_all_samp_db_01/sample_01]
.../philosopher/philosopher filter --sequential --prot 0.01 --tag rev_ --pepxml .../sample_01_fragpipe_test_closed_all_samp_db_01/sample_01 --protxml .../sample_01_fragpipe_test_closed_all_samp_db_01/combined.prot.xml --razor
time="01:57:47" level=info msg="Executing Filter  v4.8.1"
time="01:57:47" level=info msg="Processing peptide identification files"
time="01:57:47" level=info msg="Parsing .../sample_01_fragpipe_test_closed_all_samp_db_01/sample_01/interact-sample_01_calibrated.pep.xml"
time="01:58:44" level=info msg="1+ Charge profile" decoy=0 target=0
time="01:58:44" level=info msg="2+ Charge profile" decoy=435 target=20008
time="01:58:44" level=info msg="3+ Charge profile" decoy=173 target=12002
time="01:58:44" level=info msg="4+ Charge profile" decoy=49 target=2631
time="01:58:44" level=info msg="5+ Charge profile" decoy=4 target=295
time="01:58:44" level=info msg="6+ Charge profile" decoy=1 target=21
time="01:58:44" level=info msg="Database search results" ions=32986 peptides=28494 psms=35622
time="01:58:45" level=info msg="Converged to 1.00 % FDR with 34048 PSMs" decoy=340 threshold=0.777215 total=34388
time="01:58:45" level=info msg="Converged to 1.00 % FDR with 26956 Peptides" decoy=269 threshold=0.817572 total=27225
time="01:58:45" level=info msg="Converged to 1.00 % FDR with 31569 Ions" decoy=315 threshold=0.776875 total=31884
time="02:21:03" level=error msg="Cannot decode packed binary. XML syntax error on line 361982260: unexpected EOF"
panic: Cannot decode packed binary. XML syntax error on line 361982260: unexpected EOF

goroutine 1 [running]:
philosopher/lib/msg.callLogrus({0xcab9050320, 0x4f}, {0xb379d5, 0x1?})
	/workspace/philosopher/lib/msg/msg.go:319 +0x354
philosopher/lib/msg.DecodeMsgPck({0xca0640?, 0xc73993a168?}, {0xb379d5, 0x5})
	/workspace/philosopher/lib/msg/msg.go:120 +0x6e
philosopher/lib/spc.(*ProtXML).Parse(0xc002a55910, {0x7fffb4eaa687, 0x62})
	/workspace/philosopher/lib/spc/spc.go:97 +0x210
philosopher/lib/id.(*ProtXML).Read(0xc002a55bb8, {0x7fffb4eaa687?, 0xc0002b5b90?})
	/workspace/philosopher/lib/id/pro.go:116 +0x85
philosopher/lib/fil.ReadProtXMLInput({0x7fffb4eaa687?, 0xd?}, {0x7fffb4eaa617, 0x4}, 0x3ff0000000000000)
	/workspace/philosopher/lib/fil/fil.go:504 +0x9f
philosopher/lib/fil.Run({{0xc0000288a0, 0x24}, {0xc00002c8a0, 0x57}, {0xc0000288d0, 0x29}, {0xc0000fe3f0, 0x66}, {0xc00002c900, 0x5d}, ...})
	/workspace/philosopher/lib/fil/fil.go:81 +0x77a
philosopher/cmd.glob..func5(0x2610bc0?, {0xb3726a?, 0xa?, 0xa?})
	/workspace/philosopher/cmd/filter.go:43 +0x390
github.com/spf13/cobra.(*Command).execute(0x2610bc0, {0xc000286b40, 0xa, 0xa})
	/home/prvst/go/pkg/mod/github.com/spf13/[email protected]/command.go:920 +0x847
github.com/spf13/cobra.(*Command).ExecuteC(0x260f4c0)
	/home/prvst/go/pkg/mod/github.com/spf13/[email protected]/command.go:1044 +0x3bd
github.com/spf13/cobra.(*Command).Execute(...)
	/home/prvst/go/pkg/mod/github.com/spf13/[email protected]/command.go:968
philosopher/cmd.Execute()
	/workspace/philosopher/cmd/root.go:35 +0x25
main.main()
	/workspace/philosopher/main.go:25 +0x90
Process 'PhilosopherFilter' finished, exit code: 2
Process returned non-zero exit code, stopping

~~~~~~~~~~~~~~~~~~~~
Cancelling 5 remaining tasks

Best,

Fengchao

ohickl · 2023-03-30T13:49:23Z

Thanks for you swift reply!
For the db split observation, I was not referring to this error. When decreasing the split size, I would get another (msfragger) error with the suggestion to increase the slice-db value.

I am not sure what you mean by this:

Following is a "more complete" error message

This is the log for the run that arrives at the filtering step I attached or am I missing something?

prvst · 2023-03-30T14:04:33Z

Check your prot.xml file, it looks like its corrupted. The program cannot make sense of the XML structure

ohickl · 2023-03-30T14:48:31Z

It just stops at the marked line number, in the middle of the line. I will rerun once more to see, if it was bad luck. The same input with identical settings but a smaller db finishes without problems.

anesvi · 2023-03-30T14:52:35Z

Philosopher struggled with very large databases for a while. Guo Ci recently made changes to reduce the memory requirement for parsing large databases. Maybe it will resolve this issue. Perhaps you can get a pre-release version of philosopher. Fengchao, Felipe, should we ask them to try try the latest RC version?

prvst · 2023-03-30T14:55:12Z

@ohickl this is an indication that ProteinProphet crashed.

ohickl · 2023-03-31T11:15:23Z

The problem seems to be that ProteinProphet writes to /dev/mapper/root, filling it up completely and then stopping to write to the prot.xml. Not sure how that works or why it would do that. Did you encounter this problem already? Can it be redirected to another tmp dir, where there is more space?

ohickl · 2023-04-05T12:05:19Z

It does automatically write to /tmp/<fragpipe_tmp_dir> though, which seems to create the problem.
I tried some proposed solutions from e.g. Nesvilab/FragPipe#755 but they don't seem to have an effect. Can I not set a desired tmp dir for the workflow in the .workflow file or as parameter for the FraGpipe command itself, as with philosopher workspace --init --temp <path>? Maybe I missed it but i couldn't find a way.
Fragpipe seems to always automatically set it to /tmp/..., e.g.:

...
WorkspaceCleanInit [Work dir: /mnt/.../fragpipe_test_closed_all_samp_db_02]
/mnt/data/local_tools/philosopher/philosopher workspace --init --nocheck --temp /tmp/1e286c0f-ca3e-4b7a-abe8-0bc5d54f56d4
...

ohickl · 2023-04-05T13:48:04Z

Ok. I'll delete everything, reset the vars and try again.
It does write the prot.xml to temp, in my case:

(philosopher) oskar.hickl@bigmem:/mnt/...$ ll /tmp/a0fff007-b458-4d18-9a20-a194b20d73ab
total 20973488
drwxr-xr-x   2 oskar.hickl oskar.hickl          96 Apr  5 13:46 ./
drwxrwxrwt. 69 root        root               8192 Apr  5 13:39 ../
-rwxr-xr-x   1 oskar.hickl oskar.hickl       15136 Apr  5 11:50 batchcoverage*
-rw-rw-r--   1 oskar.hickl oskar.hickl 16366534656 Apr  5 13:50 combined.prot.xml
-rwxr-xr-x   1 oskar.hickl oskar.hickl      140432 Apr  5 11:50 DatabaseParser*
-rwxr-xr-x   1 oskar.hickl oskar.hickl     1909640 Apr  5 11:50 ProteinProphet*

prvst · 2023-04-05T14:02:30Z

Yes, the prot.xml file is written to the temp folder. You can change the temp location to a custom one using the --temp flag from workspace.

fcyu · 2023-04-05T14:18:49Z

Thanks @prvst . This also explains the error in Nesvilab/FragPipe#807 (comment)

Best,

Fengchao

fcyu assigned prvst Mar 30, 2023

fcyu closed this as completed Apr 4, 2023

fcyu transferred this issue from Nesvilab/FragPipe Apr 5, 2023

fcyu reopened this Apr 5, 2023

fcyu mentioned this issue Apr 5, 2023

ProteinProphet Error #261

Open

fcyu changed the title ~~Filter step fails, large db, 'Cannot decode packed binary. XML syntax error on line x: unexpected EOF'~~ prot.xml was written to the temp directory but not the result directory, which resulted in the incomplete file and crashed the filter command Apr 5, 2023

prvst closed this as completed Apr 7, 2023

Nesvilab deleted a comment from ohickl Apr 18, 2023

fcyu reopened this Apr 18, 2023

fcyu pinned this issue Apr 18, 2023

fcyu unpinned this issue Apr 18, 2023

fcyu unassigned prvst Apr 18, 2023

ohickl closed this as completed Jun 19, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

`prot.xml` was written to the temp directory but not the result directory, which resulted in the incomplete file and crashed the filter command #429

`prot.xml` was written to the temp directory but not the result directory, which resulted in the incomplete file and crashed the filter command #429

ohickl commented Mar 30, 2023

fcyu commented Mar 30, 2023

ohickl commented Mar 30, 2023

prvst commented Mar 30, 2023

ohickl commented Mar 30, 2023

anesvi commented Mar 30, 2023

prvst commented Mar 30, 2023

ohickl commented Mar 31, 2023

ohickl commented Apr 5, 2023

ohickl commented Apr 5, 2023

prvst commented Apr 5, 2023

fcyu commented Apr 5, 2023

prot.xml was written to the temp directory but not the result directory, which resulted in the incomplete file and crashed the filter command #429

prot.xml was written to the temp directory but not the result directory, which resulted in the incomplete file and crashed the filter command #429

Comments

ohickl commented Mar 30, 2023

fcyu commented Mar 30, 2023

ohickl commented Mar 30, 2023

prvst commented Mar 30, 2023

ohickl commented Mar 30, 2023

anesvi commented Mar 30, 2023

prvst commented Mar 30, 2023

ohickl commented Mar 31, 2023

ohickl commented Apr 5, 2023

ohickl commented Apr 5, 2023

prvst commented Apr 5, 2023

fcyu commented Apr 5, 2023

`prot.xml` was written to the temp directory but not the result directory, which resulted in the incomplete file and crashed the filter command #429

`prot.xml` was written to the temp directory but not the result directory, which resulted in the incomplete file and crashed the filter command #429