12 May 2021 04:20:53,711 INFO : Starting to run task 'org.labkey.targetedms.pipeline.TargetedMSImportTask' at location 'webserver-high-priority'
12 May 2021 04:20:53,716 INFO : Starting to import Skyline document from 210512_GluC_P100_upload_2021-05-12_13-21-08.sky.zip
12 May 2021 04:20:53,716 INFO : Expanding GluC_P100_CE.optdb
12 May 2021 04:20:53,724 INFO : Expanding P100MM4_GluC_Spectrallibrary.blib
12 May 2021 04:20:53,728 INFO : Expanding P100MM3_GluC_Spectrallibrary.blib
12 May 2021 04:20:53,732 INFO : Expanding P100MM2_GluC_Spectrallibrary.blib
12 May 2021 04:20:53,737 INFO : Expanding P100MM1_GluC_Spectrallibrary.blib
12 May 2021 04:20:53,741 INFO : Expanding 210512_GluC_P100_upload.sky.view
12 May 2021 04:20:53,742 INFO : Expanding 210512_GluC_P100_upload.sky
12 May 2021 04:20:53,749 INFO : Expanding 210512_GluC_P100_upload.skyl
12 May 2021 04:20:53,764 INFO : 1% Done
12 May 2021 04:20:53,793 WARN : Unable to find file /data/labkey/files/KTH - Uhlen Lab/Alternative proteases - Master's thesis/GluC/@files/210512_GluC_P100_upload_2021-05-12_13-21-08/210512_GluC_P100_upload.skyd, unable to import chromatograms
12 May 2021 04:20:53,856 INFO : Inserting sp|P00738|HPT_HUMAN
12 May 2021 04:20:53,860 INFO : 3% Done
12 May 2021 04:20:53,878 INFO : 4% Done
12 May 2021 04:20:53,907 INFO : 7% Done
12 May 2021 04:20:53,927 DEBUG: Total peptides inserted: 3
12 May 2021 04:20:53,931 INFO : Inserting sp|P01009|A1AT_HUMAN
12 May 2021 04:20:53,934 INFO : 8% Done
12 May 2021 04:20:53,944 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:53,948 INFO : Inserting sp|P01011|AACT_HUMAN
12 May 2021 04:20:53,950 INFO : 9% Done
12 May 2021 04:20:53,964 INFO : 10% Done
12 May 2021 04:20:53,973 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:53,976 INFO : Inserting sp|P02647|APOA1_HUMAN
12 May 2021 04:20:53,979 INFO : 11% Done
12 May 2021 04:20:53,990 INFO : 13% Done
12 May 2021 04:20:54,008 INFO : 14% Done
12 May 2021 04:20:54,017 DEBUG: Total peptides inserted: 4
12 May 2021 04:20:54,019 INFO : 15% Done
12 May 2021 04:20:54,022 INFO : Inserting sp|P02679|FIBG_HUMAN
12 May 2021 04:20:54,024 INFO : 16% Done
12 May 2021 04:20:54,034 INFO : 18% Done
12 May 2021 04:20:54,049 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,051 INFO : Inserting sp|P02765|FETUA_HUMAN
12 May 2021 04:20:54,054 INFO : 19% Done
12 May 2021 04:20:54,063 INFO : 20% Done
12 May 2021 04:20:54,070 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,073 INFO : Inserting sp|P02774|VTDB_HUMAN
12 May 2021 04:20:54,075 INFO : 21% Done
12 May 2021 04:20:54,084 INFO : 22% Done
12 May 2021 04:20:54,090 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,093 INFO : Inserting sp|P05090|APOD_HUMAN
12 May 2021 04:20:54,095 INFO : 24% Done
12 May 2021 04:20:54,103 INFO : 25% Done
12 May 2021 04:20:54,117 INFO : 26% Done
12 May 2021 04:20:54,129 DEBUG: Total peptides inserted: 4
12 May 2021 04:20:54,132 INFO : Inserting sp|P06727|APOA4_HUMAN
12 May 2021 04:20:54,135 INFO : 27% Done
12 May 2021 04:20:54,148 INFO : 28% Done
12 May 2021 04:20:54,161 INFO : 29% Done
12 May 2021 04:20:54,173 INFO : 30% Done
12 May 2021 04:20:54,185 INFO : 31% Done
12 May 2021 04:20:54,194 DEBUG: Total peptides inserted: 5
12 May 2021 04:20:54,197 INFO : Inserting sp|P18428|LBP_HUMAN
12 May 2021 04:20:54,200 INFO : 32% Done
12 May 2021 04:20:54,210 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,213 INFO : Inserting sp|Q9NQ79|CRAC1_HUMAN
12 May 2021 04:20:54,215 INFO : 33% Done
12 May 2021 04:20:54,225 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,227 INFO : 34% Done
12 May 2021 04:20:54,230 INFO : Inserting sp|O14791|APOL1_HUMAN
12 May 2021 04:20:54,232 INFO : 35% Done
12 May 2021 04:20:54,241 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,244 INFO : Inserting sp|O43866|CD5L_HUMAN
12 May 2021 04:20:54,246 INFO : 36% Done
12 May 2021 04:20:54,255 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,257 INFO : Inserting sp|P00747|PLMN_HUMAN
12 May 2021 04:20:54,260 INFO : 38% Done
12 May 2021 04:20:54,268 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,271 INFO : Inserting sp|P00751|CFAB_HUMAN
12 May 2021 04:20:54,280 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,281 INFO : 39% Done
12 May 2021 04:20:54,283 INFO : Inserting sp|P01591|IGJ_HUMAN
12 May 2021 04:20:54,285 INFO : 40% Done
12 May 2021 04:20:54,295 INFO : 41% Done
12 May 2021 04:20:54,301 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,303 INFO : Inserting sp|P04003|C4BPA_HUMAN
12 May 2021 04:20:54,306 INFO : 42% Done
12 May 2021 04:20:54,314 INFO : 44% Done
12 May 2021 04:20:54,328 DEBUG: Total peptides inserted: 3
12 May 2021 04:20:54,331 INFO : Inserting sp|P05160|F13B_HUMAN
12 May 2021 04:20:54,333 INFO : 46% Done
12 May 2021 04:20:54,340 INFO : 47% Done
12 May 2021 04:20:54,347 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,349 INFO : Inserting sp|P05452|TETN_HUMAN
12 May 2021 04:20:54,351 INFO : 48% Done
12 May 2021 04:20:54,358 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,360 INFO : Inserting sp|P07360|CO8G_HUMAN
12 May 2021 04:20:54,362 INFO : 49% Done
12 May 2021 04:20:54,368 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,370 INFO : 50% Done
12 May 2021 04:20:54,372 INFO : Inserting sp|P08697|A2AP_HUMAN
12 May 2021 04:20:54,381 INFO : 51% Done
12 May 2021 04:20:54,388 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,390 INFO : 52% Done
12 May 2021 04:20:54,391 INFO : Inserting sp|P13671|CO6_HUMAN
12 May 2021 04:20:54,393 INFO : 53% Done
12 May 2021 04:20:54,405 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,406 INFO : 54% Done
12 May 2021 04:20:54,408 INFO : Inserting sp|P51884|LUM_HUMAN
12 May 2021 04:20:54,410 INFO : 55% Done
12 May 2021 04:20:54,418 INFO : 56% Done
12 May 2021 04:20:54,424 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,426 INFO : Inserting sp|P80108|PHLD_HUMAN
12 May 2021 04:20:54,428 INFO : 57% Done
12 May 2021 04:20:54,434 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,436 INFO : 58% Done
12 May 2021 04:20:54,438 INFO : Inserting sp|Q04756|HGFA_HUMAN
12 May 2021 04:20:54,440 INFO : 59% Done
12 May 2021 04:20:54,446 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,448 INFO : Inserting sp|Q14624|ITIH4_HUMAN
12 May 2021 04:20:54,450 INFO : 60% Done
12 May 2021 04:20:54,458 INFO : 61% Done
12 May 2021 04:20:54,464 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,466 INFO : 62% Done
12 May 2021 04:20:54,468 INFO : Inserting sp|P00734|THRB_HUMAN
12 May 2021 04:20:54,470 INFO : 63% Done
12 May 2021 04:20:54,481 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,483 INFO : 64% Done
12 May 2021 04:20:54,485 INFO : Inserting sp|P01008|ANT3_HUMAN
12 May 2021 04:20:54,487 INFO : 65% Done
12 May 2021 04:20:54,501 INFO : 67% Done
12 May 2021 04:20:54,507 DEBUG: Total peptides inserted: 3
12 May 2021 04:20:54,509 INFO : Inserting sp|P02671|FIBA_HUMAN
12 May 2021 04:20:54,511 INFO : 68% Done
12 May 2021 04:20:54,517 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,519 INFO : Inserting sp|P02790|HEMO_HUMAN
12 May 2021 04:20:54,521 INFO : 69% Done
12 May 2021 04:20:54,527 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,529 INFO : Inserting sp|P04196|HRG_HUMAN
12 May 2021 04:20:54,531 INFO : 70% Done
12 May 2021 04:20:54,538 INFO : 71% Done
12 May 2021 04:20:54,543 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,544 INFO : 72% Done
12 May 2021 04:20:54,546 INFO : Inserting sp|P04264|K2C1_HUMAN
12 May 2021 04:20:54,548 INFO : 73% Done
12 May 2021 04:20:54,554 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,556 INFO : Inserting sp|P05546|HEP2_HUMAN
12 May 2021 04:20:54,558 INFO : 74% Done
12 May 2021 04:20:54,564 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,566 INFO : Inserting sp|P07357|CO8A_HUMAN
12 May 2021 04:20:54,574 INFO : 75% Done
12 May 2021 04:20:54,579 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,581 INFO : Inserting sp|P20851|C4BPB_HUMAN
12 May 2021 04:20:54,583 INFO : 76% Done
12 May 2021 04:20:54,591 INFO : 78% Done
12 May 2021 04:20:54,602 DEBUG: Total peptides inserted: 3
12 May 2021 04:20:54,604 INFO : 79% Done
12 May 2021 04:20:54,606 INFO : Inserting sp|O75882|ATRN_HUMAN
12 May 2021 04:20:54,608 INFO : 80% Done
12 May 2021 04:20:54,614 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,616 INFO : Inserting sp|P00742|FA10_HUMAN
12 May 2021 04:20:54,618 INFO : 81% Done
12 May 2021 04:20:54,624 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,626 INFO : Inserting sp|P04278|SHBG_HUMAN
12 May 2021 04:20:54,628 INFO : 83% Done
12 May 2021 04:20:54,633 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,635 INFO : Inserting sp|P07359|GP1BA_HUMAN
12 May 2021 04:20:54,638 INFO : 84% Done
12 May 2021 04:20:54,644 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,646 INFO : Inserting sp|P08571|CD14_HUMAN
12 May 2021 04:20:54,647 INFO : 85% Done
12 May 2021 04:20:54,653 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,655 INFO : Inserting sp|P13598|ICAM2_HUMAN
12 May 2021 04:20:54,657 INFO : 86% Done
12 May 2021 04:20:54,663 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,665 INFO : 87% Done
12 May 2021 04:20:54,667 INFO : Inserting sp|P19823|ITIH2_HUMAN
12 May 2021 04:20:54,674 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,675 INFO : 88% Done
12 May 2021 04:20:54,677 INFO : Inserting sp|P20742|PZP_HUMAN
12 May 2021 04:20:54,679 INFO : 89% Done
12 May 2021 04:20:54,687 INFO : 90% Done
12 May 2021 04:20:54,693 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,695 INFO : Inserting sp|P22792|CPN2_HUMAN
12 May 2021 04:20:54,697 INFO : 91% Done
12 May 2021 04:20:54,703 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,705 INFO : Inserting sp|P27169|PON1_HUMAN
12 May 2021 04:20:54,707 INFO : 93% Done
12 May 2021 04:20:54,713 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,715 INFO : Inserting sp|P29622|KAIN_HUMAN
12 May 2021 04:20:54,721 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:54,723 INFO : 94% Done
12 May 2021 04:20:54,725 INFO : Inserting sp|P43652|AFAM_HUMAN
12 May 2021 04:20:54,727 INFO : 95% Done
12 May 2021 04:20:54,735 INFO : 96% Done
12 May 2021 04:20:54,740 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,742 INFO : Inserting sp|Q06033|ITIH3_HUMAN
12 May 2021 04:20:54,745 INFO : 97% Done
12 May 2021 04:20:54,753 INFO : 98% Done
12 May 2021 04:20:54,759 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:54,760 INFO : Done parsing Skyline document.
12 May 2021 04:20:54,881 ERROR: Import failed
org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "uix_auditlogentry_document"
Detail: Key (documentguid, entryhash)=(a34c4241-4afe-4955-8ea7-bd457546e203, jdZ1LXpMhygvzC+JyoW1MDlzAPQ=) already exists.
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2532)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2267)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:312)
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:448)
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:369)
at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:153)
at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:103)
at org.apache.tomcat.dbcp.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:122)
at org.apache.tomcat.dbcp.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:122)
at org.labkey.api.data.dialect.StatementWrapper.executeQuery(StatementWrapper.java:1245)
at org.labkey.api.data.dialect.PostgreSql91Dialect.executeWithResults(PostgreSql91Dialect.java:274)
at org.labkey.api.data.Table.insert(Table.java:781)
at org.labkey.targetedms.parser.skyaudit.AuditLogEntry.persist(AuditLogEntry.java:305)
at org.labkey.targetedms.SkylineAuditLogManager.persistAuditLog(SkylineAuditLogManager.java:278)
at org.labkey.targetedms.SkylineAuditLogManager.importAuditLogFile(SkylineAuditLogManager.java:110)
at org.labkey.targetedms.SkylineDocImporter.importSkylineDoc(SkylineDocImporter.java:450)
at org.labkey.targetedms.SkylineDocImporter.importRun(SkylineDocImporter.java:244)
at org.labkey.targetedms.pipeline.TargetedMSImportTask.run(TargetedMSImportTask.java:63)
at org.labkey.api.pipeline.PipelineJob.runActiveTask(PipelineJob.java:818)
at org.labkey.api.pipeline.PipelineJob.run(PipelineJob.java:1055)
at org.labkey.pipeline.mule.PipelineJobRunner.run(PipelineJobRunner.java:40)
at jdk.internal.reflect.GeneratedMethodAccessor1516.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:567)
at org.mule.impl.model.resolvers.DynamicEntryPoint.invokeMethod(DynamicEntryPoint.java:312)
at org.mule.impl.model.resolvers.DynamicEntryPoint.invoke(DynamicEntryPoint.java:259)
at org.mule.impl.DefaultLifecycleAdapter.intercept(DefaultLifecycleAdapter.java:193)
at org.mule.impl.InterceptorsInvoker.execute(InterceptorsInvoker.java:47)
at org.mule.impl.model.DefaultMuleProxy.run(DefaultMuleProxy.java:470)
at org.mule.impl.work.WorkerContext.run(WorkerContext.java:310)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$CallerRunsPolicy.rejectedExecution(ThreadPoolExecutor.java:1486)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:391)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:865)
at org.mule.impl.work.ScheduleWorkExecutor.doExecute(ScheduleWorkExecutor.java:39)
at org.mule.impl.work.MuleWorkManager.executeWork(MuleWorkManager.java:277)
at org.mule.impl.work.MuleWorkManager.scheduleWork(MuleWorkManager.java:244)
at org.mule.impl.model.seda.SedaComponent.run(SedaComponent.java:483)
at org.mule.impl.work.WorkerContext.run(WorkerContext.java:310)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.base/java.lang.Thread.run(Thread.java:831)
12 May 2021 04:20:54,896 INFO : Failed to complete task 'org.labkey.targetedms.pipeline.TargetedMSImportTask'
12 May 2021 04:20:54,899 ERROR: ERROR: duplicate key value violates unique constraint "uix_auditlogentry_document"
Detail: Key (documentguid, entryhash)=(a34c4241-4afe-4955-8ea7-bd457546e203, jdZ1LXpMhygvzC+JyoW1MDlzAPQ=) already exists.
org.labkey.api.pipeline.PipelineJobException: ERROR: duplicate key value violates unique constraint "uix_auditlogentry_document"
Detail: Key (documentguid, entryhash)=(a34c4241-4afe-4955-8ea7-bd457546e203, jdZ1LXpMhygvzC+JyoW1MDlzAPQ=) already exists.
at org.labkey.targetedms.SkylineDocImporter.importRun(SkylineDocImporter.java:268)
at org.labkey.targetedms.pipeline.TargetedMSImportTask.run(TargetedMSImportTask.java:63)
at org.labkey.api.pipeline.PipelineJob.runActiveTask(PipelineJob.java:818)
at org.labkey.api.pipeline.PipelineJob.run(PipelineJob.java:1055)
at org.labkey.pipeline.mule.PipelineJobRunner.run(PipelineJobRunner.java:40)
at jdk.internal.reflect.GeneratedMethodAccessor1516.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:567)
at org.mule.impl.model.resolvers.DynamicEntryPoint.invokeMethod(DynamicEntryPoint.java:312)
at org.mule.impl.model.resolvers.DynamicEntryPoint.invoke(DynamicEntryPoint.java:259)
at org.mule.impl.DefaultLifecycleAdapter.intercept(DefaultLifecycleAdapter.java:193)
at org.mule.impl.InterceptorsInvoker.execute(InterceptorsInvoker.java:47)
at org.mule.impl.model.DefaultMuleProxy.run(DefaultMuleProxy.java:470)
at org.mule.impl.work.WorkerContext.run(WorkerContext.java:310)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$CallerRunsPolicy.rejectedExecution(ThreadPoolExecutor.java:1486)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:391)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:865)
at org.mule.impl.work.ScheduleWorkExecutor.doExecute(ScheduleWorkExecutor.java:39)
at org.mule.impl.work.MuleWorkManager.executeWork(MuleWorkManager.java:277)
at org.mule.impl.work.MuleWorkManager.scheduleWork(MuleWorkManager.java:244)
at org.mule.impl.model.seda.SedaComponent.run(SedaComponent.java:483)
at org.mule.impl.work.WorkerContext.run(WorkerContext.java:310)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.base/java.lang.Thread.run(Thread.java:831)
Caused by: org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique constraint "uix_auditlogentry_document"
Detail: Key (documentguid, entryhash)=(a34c4241-4afe-4955-8ea7-bd457546e203, jdZ1LXpMhygvzC+JyoW1MDlzAPQ=) already exists.
at org.labkey.api.data.Table.insert(Table.java:800)
at org.labkey.targetedms.parser.skyaudit.AuditLogEntry.persist(AuditLogEntry.java:305)
at org.labkey.targetedms.SkylineAuditLogManager.persistAuditLog(SkylineAuditLogManager.java:278)
at org.labkey.targetedms.SkylineAuditLogManager.importAuditLogFile(SkylineAuditLogManager.java:110)
at org.labkey.targetedms.SkylineDocImporter.importSkylineDoc(SkylineDocImporter.java:450)
at org.labkey.targetedms.SkylineDocImporter.importRun(SkylineDocImporter.java:244)
... 24 more