12 May 2021 04:11:48,013 INFO : Starting to run task 'org.labkey.targetedms.pipeline.TargetedMSImportTask' at location 'webserver-high-priority'
12 May 2021 04:11:48,018 INFO : Starting to import Skyline document from 210512_GluC_P100_upload_2021-05-12_13-11-27.sky.zip
12 May 2021 04:11:48,019 INFO : Expanding 210203_HumanProteomeUniprot.protdb
12 May 2021 04:11:51,402 INFO : Expanding GluC_P100_CE.optdb
12 May 2021 04:11:51,407 INFO : Expanding P100MM4_GluC_Spectrallibrary.blib
12 May 2021 04:11:51,424 INFO : Expanding P100MM1_GluC_Spectrallibrary.blib
12 May 2021 04:11:51,427 INFO : Expanding P100MM2_GluC_Spectrallibrary.blib
12 May 2021 04:11:51,429 INFO : Expanding P100MM3_GluC_Spectrallibrary.blib
12 May 2021 04:11:51,432 INFO : Expanding 210512_GluC_P100_upload.sky.view
12 May 2021 04:11:51,433 INFO : Expanding 210512_GluC_P100_upload.sky
12 May 2021 04:11:51,439 INFO : Expanding 210512_GluC_P100_upload.skyl
12 May 2021 04:11:51,454 INFO : 1% Done
12 May 2021 04:11:51,475 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-11-27/210512_GluC_P100_upload.skyd, unable to import chromatograms
12 May 2021 04:11:51,508 INFO : Inserting QTag
12 May 2021 04:11:51,512 INFO : 2% Done
12 May 2021 04:11:51,520 INFO : 3% Done
12 May 2021 04:11:51,526 INFO : 4% Done
12 May 2021 04:11:51,539 INFO : 5% Done
12 May 2021 04:11:51,543 DEBUG: Total peptides inserted: 5
12 May 2021 04:11:51,545 INFO : Inserting sp|P00738|HPT_HUMAN
12 May 2021 04:11:51,548 INFO : 6% Done
12 May 2021 04:11:51,556 INFO : 8% Done
12 May 2021 04:11:51,572 INFO : 10% Done
12 May 2021 04:11:51,582 DEBUG: Total peptides inserted: 3
12 May 2021 04:11:51,584 INFO : Inserting sp|P01009|A1AT_HUMAN
12 May 2021 04:11:51,587 INFO : 11% Done
12 May 2021 04:11:51,593 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:51,595 INFO : 12% Done
12 May 2021 04:11:51,597 INFO : Inserting sp|P01011|AACT_HUMAN
12 May 2021 04:11:51,606 INFO : 13% Done
12 May 2021 04:11:51,612 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:51,614 INFO : 14% Done
12 May 2021 04:11:51,616 INFO : Inserting sp|P02647|APOA1_HUMAN
12 May 2021 04:11:51,624 INFO : 15% Done
12 May 2021 04:11:51,632 INFO : 17% Done
12 May 2021 04:11:51,643 DEBUG: Total peptides inserted: 4
12 May 2021 04:11:51,645 INFO : Inserting sp|P02679|FIBG_HUMAN
12 May 2021 04:11:51,647 INFO : 19% Done
12 May 2021 04:11:51,655 INFO : 20% Done
12 May 2021 04:11:51,665 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:51,668 INFO : 21% Done
12 May 2021 04:11:51,669 INFO : Inserting sp|P02765|FETUA_HUMAN
12 May 2021 04:11:51,671 INFO : 22% Done
12 May 2021 04:11:51,683 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:51,685 INFO : 23% Done
12 May 2021 04:11:51,687 INFO : Inserting sp|P02774|VTDB_HUMAN
12 May 2021 04:11:51,689 INFO : 24% Done
12 May 2021 04:11:51,697 INFO : 25% Done
12 May 2021 04:11:51,702 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:51,704 INFO : Inserting sp|P05090|APOD_HUMAN
12 May 2021 04:11:51,711 INFO : 26% Done
12 May 2021 04:11:51,721 INFO : 27% Done
12 May 2021 04:11:51,736 INFO : 28% Done
12 May 2021 04:11:51,746 DEBUG: Total peptides inserted: 4
12 May 2021 04:11:51,749 INFO : 29% Done
12 May 2021 04:11:51,756 INFO : Inserting sp|P06727|APOA4_HUMAN
12 May 2021 04:11:51,769 INFO : 30% Done
12 May 2021 04:11:51,781 INFO : 31% Done
12 May 2021 04:11:51,792 INFO : 32% Done
12 May 2021 04:11:51,802 INFO : 34% Done
12 May 2021 04:11:51,810 DEBUG: Total peptides inserted: 5
12 May 2021 04:11:51,813 INFO : Inserting sp|P18428|LBP_HUMAN
12 May 2021 04:11:51,821 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:51,824 INFO : 35% Done
12 May 2021 04:11:51,826 INFO : Inserting sp|Q9NQ79|CRAC1_HUMAN
12 May 2021 04:11:51,829 INFO : 36% Done
12 May 2021 04:11:51,836 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:51,839 INFO : Inserting sp|O14791|APOL1_HUMAN
12 May 2021 04:11:51,841 INFO : 37% Done
12 May 2021 04:11:51,849 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:51,851 INFO : Inserting sp|O43866|CD5L_HUMAN
12 May 2021 04:11:51,854 INFO : 38% Done
12 May 2021 04:11:51,861 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:51,863 INFO : 39% Done
12 May 2021 04:11:51,865 INFO : Inserting sp|P00747|PLMN_HUMAN
12 May 2021 04:11:51,872 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:51,874 INFO : 40% Done
12 May 2021 04:11:51,877 INFO : Inserting sp|P00751|CFAB_HUMAN
12 May 2021 04:11:51,879 INFO : 41% Done
12 May 2021 04:11:51,885 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:51,888 INFO : Inserting sp|P01591|IGJ_HUMAN
12 May 2021 04:11:51,890 INFO : 42% Done
12 May 2021 04:11:51,899 INFO : 43% Done
12 May 2021 04:11:51,905 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:51,907 INFO : Inserting sp|P04003|C4BPA_HUMAN
12 May 2021 04:11:51,909 INFO : 44% Done
12 May 2021 04:11:51,916 INFO : 45% Done
12 May 2021 04:11:51,924 INFO : 46% Done
12 May 2021 04:11:51,930 DEBUG: Total peptides inserted: 3
12 May 2021 04:11:51,932 INFO : Inserting sp|P05160|F13B_HUMAN
12 May 2021 04:11:51,934 INFO : 47% Done
12 May 2021 04:11:51,958 INFO : 49% Done
12 May 2021 04:11:51,968 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:51,972 INFO : Inserting sp|P05452|TETN_HUMAN
12 May 2021 04:11:51,983 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:51,985 INFO : 50% Done
12 May 2021 04:11:51,988 INFO : Inserting sp|P07360|CO8G_HUMAN
12 May 2021 04:11:51,990 INFO : 51% Done
12 May 2021 04:11:51,998 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,002 INFO : Inserting sp|P08697|A2AP_HUMAN
12 May 2021 04:11:52,004 INFO : 52% Done
12 May 2021 04:11:52,014 INFO : 53% Done
12 May 2021 04:11:52,023 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:52,026 INFO : 54% Done
12 May 2021 04:11:52,029 INFO : Inserting sp|P13671|CO6_HUMAN
12 May 2021 04:11:52,038 INFO : 55% Done
12 May 2021 04:11:52,046 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:52,048 INFO : Inserting sp|P51884|LUM_HUMAN
12 May 2021 04:11:52,051 INFO : 57% Done
12 May 2021 04:11:52,066 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:52,068 INFO : 58% Done
12 May 2021 04:11:52,071 INFO : Inserting sp|P80108|PHLD_HUMAN
12 May 2021 04:11:52,073 INFO : 59% Done
12 May 2021 04:11:52,080 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,083 INFO : Inserting sp|Q04756|HGFA_HUMAN
12 May 2021 04:11:52,085 INFO : 60% Done
12 May 2021 04:11:52,092 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,094 INFO : Inserting sp|Q14624|ITIH4_HUMAN
12 May 2021 04:11:52,097 INFO : 61% Done
12 May 2021 04:11:52,105 INFO : 62% Done
12 May 2021 04:11:52,112 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:52,114 INFO : Inserting sp|P00734|THRB_HUMAN
12 May 2021 04:11:52,116 INFO : 64% Done
12 May 2021 04:11:52,127 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,130 INFO : Inserting sp|P01008|ANT3_HUMAN
12 May 2021 04:11:52,132 INFO : 66% Done
12 May 2021 04:11:52,140 INFO : 67% Done
12 May 2021 04:11:52,152 DEBUG: Total peptides inserted: 3
12 May 2021 04:11:52,154 INFO : 68% Done
12 May 2021 04:11:52,157 INFO : Inserting sp|P02671|FIBA_HUMAN
12 May 2021 04:11:52,159 INFO : 69% Done
12 May 2021 04:11:52,165 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,167 INFO : Inserting sp|P02790|HEMO_HUMAN
12 May 2021 04:11:52,169 INFO : 70% Done
12 May 2021 04:11:52,176 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,179 INFO : Inserting sp|P04196|HRG_HUMAN
12 May 2021 04:11:52,182 INFO : 72% Done
12 May 2021 04:11:52,194 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:52,196 INFO : Inserting sp|P04264|K2C1_HUMAN
12 May 2021 04:11:52,200 INFO : 74% Done
12 May 2021 04:11:52,206 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,208 INFO : Inserting sp|P05546|HEP2_HUMAN
12 May 2021 04:11:52,214 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,216 INFO : Inserting sp|P07357|CO8A_HUMAN
12 May 2021 04:11:52,219 INFO : 75% Done
12 May 2021 04:11:52,226 INFO : 76% Done
12 May 2021 04:11:52,231 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:52,233 INFO : Inserting sp|P20851|C4BPB_HUMAN
12 May 2021 04:11:52,236 INFO : 77% Done
12 May 2021 04:11:52,245 INFO : 78% Done
12 May 2021 04:11:52,252 INFO : 79% Done
12 May 2021 04:11:52,258 DEBUG: Total peptides inserted: 3
12 May 2021 04:11:52,260 INFO : Inserting sp|O75882|ATRN_HUMAN
12 May 2021 04:11:52,262 INFO : 81% Done
12 May 2021 04:11:52,268 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,270 INFO : Inserting sp|P00742|FA10_HUMAN
12 May 2021 04:11:52,276 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,278 INFO : 82% Done
12 May 2021 04:11:52,280 INFO : Inserting sp|P04278|SHBG_HUMAN
12 May 2021 04:11:52,283 INFO : 83% Done
12 May 2021 04:11:52,288 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,290 INFO : Inserting sp|P07359|GP1BA_HUMAN
12 May 2021 04:11:52,293 INFO : 84% Done
12 May 2021 04:11:52,298 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,300 INFO : Inserting sp|P08571|CD14_HUMAN
12 May 2021 04:11:52,303 INFO : 85% Done
12 May 2021 04:11:52,308 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,311 INFO : 86% Done
12 May 2021 04:11:52,313 INFO : Inserting sp|P13598|ICAM2_HUMAN
12 May 2021 04:11:52,315 INFO : 87% Done
12 May 2021 04:11:52,321 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,323 INFO : Inserting sp|P19823|ITIH2_HUMAN
12 May 2021 04:11:52,326 INFO : 88% Done
12 May 2021 04:11:52,332 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,334 INFO : Inserting sp|P20742|PZP_HUMAN
12 May 2021 04:11:52,337 INFO : 89% Done
12 May 2021 04:11:52,345 INFO : 90% Done
12 May 2021 04:11:52,351 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:52,353 INFO : 91% Done
12 May 2021 04:11:52,355 INFO : Inserting sp|P22792|CPN2_HUMAN
12 May 2021 04:11:52,358 INFO : 92% Done
12 May 2021 04:11:52,363 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,365 INFO : Inserting sp|P27169|PON1_HUMAN
12 May 2021 04:11:52,371 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,374 INFO : 93% Done
12 May 2021 04:11:52,376 INFO : Inserting sp|P29622|KAIN_HUMAN
12 May 2021 04:11:52,379 INFO : 94% Done
12 May 2021 04:11:52,386 DEBUG: Total peptides inserted: 1
12 May 2021 04:11:52,388 INFO : Inserting sp|P43652|AFAM_HUMAN
12 May 2021 04:11:52,391 INFO : 95% Done
12 May 2021 04:11:52,399 INFO : 96% Done
12 May 2021 04:11:52,405 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:52,407 INFO : 97% Done
12 May 2021 04:11:52,409 INFO : Inserting sp|Q06033|ITIH3_HUMAN
12 May 2021 04:11:52,417 INFO : 98% Done
12 May 2021 04:11:52,422 DEBUG: Total peptides inserted: 2
12 May 2021 04:11:52,423 INFO : Done parsing Skyline document.
12 May 2021 04:11:52,542 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:11:52,593 INFO : Failed to complete task 'org.labkey.targetedms.pipeline.TargetedMSImportTask'
12 May 2021 04:11:52,596 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