12 May 2021 04:08:38,541 INFO : Starting to run task 'org.labkey.targetedms.pipeline.TargetedMSImportTask' at location 'webserver-high-priority'
12 May 2021 04:08:38,545 INFO : Starting to import Skyline document from 210512_GluC_P100_upload_2021-05-12_13-08-21.sky.zip
12 May 2021 04:08:38,545 INFO : Expanding 210203_HumanProteomeUniprot.protdb
12 May 2021 04:08:41,459 INFO : Expanding GluC_P100_CE.optdb
12 May 2021 04:08:41,463 INFO : Expanding P100MM4_GluC_Spectrallibrary.blib
12 May 2021 04:08:41,465 INFO : Expanding P100MM1_GluC_Spectrallibrary.blib
12 May 2021 04:08:41,470 INFO : Expanding P100MM2_GluC_Spectrallibrary.blib
12 May 2021 04:08:41,480 INFO : Expanding P100MM3_GluC_Spectrallibrary.blib
12 May 2021 04:08:41,481 INFO : Expanding 210512_GluC_P100_upload.sky.view
12 May 2021 04:08:41,483 INFO : Expanding 210512_GluC_P100_upload.sky
12 May 2021 04:08:41,486 INFO : Expanding 210512_GluC_P100_upload.skyl
12 May 2021 04:08:41,500 INFO : 1% Done
12 May 2021 04:08:41,510 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-08-21/210512_GluC_P100_upload.skyd, unable to import chromatograms
12 May 2021 04:08:41,563 INFO : Inserting QTag
12 May 2021 04:08:41,567 INFO : 2% Done
12 May 2021 04:08:41,577 INFO : 3% Done
12 May 2021 04:08:41,584 INFO : 4% Done
12 May 2021 04:08:41,599 INFO : 5% Done
12 May 2021 04:08:41,604 DEBUG: Total peptides inserted: 5
12 May 2021 04:08:41,607 INFO : Inserting sp|P00738|HPT_HUMAN
12 May 2021 04:08:41,609 INFO : 6% Done
12 May 2021 04:08:41,620 INFO : 8% Done
12 May 2021 04:08:41,637 INFO : 10% Done
12 May 2021 04:08:41,649 DEBUG: Total peptides inserted: 3
12 May 2021 04:08:41,652 INFO : Inserting sp|P01009|A1AT_HUMAN
12 May 2021 04:08:41,654 INFO : 11% Done
12 May 2021 04:08:41,661 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:41,663 INFO : 12% Done
12 May 2021 04:08:41,666 INFO : Inserting sp|P01011|AACT_HUMAN
12 May 2021 04:08:41,677 INFO : 13% Done
12 May 2021 04:08:41,684 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:41,686 INFO : 14% Done
12 May 2021 04:08:41,688 INFO : Inserting sp|P02647|APOA1_HUMAN
12 May 2021 04:08:41,698 INFO : 15% Done
12 May 2021 04:08:41,706 INFO : 17% Done
12 May 2021 04:08:41,717 DEBUG: Total peptides inserted: 4
12 May 2021 04:08:41,719 INFO : Inserting sp|P02679|FIBG_HUMAN
12 May 2021 04:08:41,722 INFO : 19% Done
12 May 2021 04:08:41,730 INFO : 20% Done
12 May 2021 04:08:41,741 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:41,743 INFO : 21% Done
12 May 2021 04:08:41,745 INFO : Inserting sp|P02765|FETUA_HUMAN
12 May 2021 04:08:41,747 INFO : 22% Done
12 May 2021 04:08:41,758 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:41,760 INFO : 23% Done
12 May 2021 04:08:41,762 INFO : Inserting sp|P02774|VTDB_HUMAN
12 May 2021 04:08:41,763 INFO : 24% Done
12 May 2021 04:08:41,770 INFO : 25% Done
12 May 2021 04:08:41,775 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:41,777 INFO : Inserting sp|P05090|APOD_HUMAN
12 May 2021 04:08:41,785 INFO : 26% Done
12 May 2021 04:08:41,792 INFO : 27% Done
12 May 2021 04:08:41,799 INFO : 28% Done
12 May 2021 04:08:41,805 DEBUG: Total peptides inserted: 4
12 May 2021 04:08:41,806 INFO : 29% Done
12 May 2021 04:08:41,815 INFO : Inserting sp|P06727|APOA4_HUMAN
12 May 2021 04:08:41,831 INFO : 30% Done
12 May 2021 04:08:41,845 INFO : 31% Done
12 May 2021 04:08:41,857 INFO : 32% Done
12 May 2021 04:08:41,869 INFO : 34% Done
12 May 2021 04:08:41,878 DEBUG: Total peptides inserted: 5
12 May 2021 04:08:41,881 INFO : Inserting sp|P18428|LBP_HUMAN
12 May 2021 04:08:41,890 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:41,893 INFO : 35% Done
12 May 2021 04:08:41,896 INFO : Inserting sp|Q9NQ79|CRAC1_HUMAN
12 May 2021 04:08:41,898 INFO : 36% Done
12 May 2021 04:08:41,907 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:41,910 INFO : Inserting sp|O14791|APOL1_HUMAN
12 May 2021 04:08:41,911 INFO : 37% Done
12 May 2021 04:08:41,919 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:41,922 INFO : Inserting sp|O43866|CD5L_HUMAN
12 May 2021 04:08:41,924 INFO : 38% Done
12 May 2021 04:08:41,931 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:41,932 INFO : 39% Done
12 May 2021 04:08:41,935 INFO : Inserting sp|P00747|PLMN_HUMAN
12 May 2021 04:08:41,942 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:41,943 INFO : 40% Done
12 May 2021 04:08:41,946 INFO : Inserting sp|P00751|CFAB_HUMAN
12 May 2021 04:08:41,948 INFO : 41% Done
12 May 2021 04:08:41,954 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:41,957 INFO : Inserting sp|P01591|IGJ_HUMAN
12 May 2021 04:08:41,959 INFO : 42% Done
12 May 2021 04:08:41,967 INFO : 43% Done
12 May 2021 04:08:41,973 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:41,975 INFO : Inserting sp|P04003|C4BPA_HUMAN
12 May 2021 04:08:41,977 INFO : 44% Done
12 May 2021 04:08:41,985 INFO : 45% Done
12 May 2021 04:08:41,993 INFO : 46% Done
12 May 2021 04:08:41,999 DEBUG: Total peptides inserted: 3
12 May 2021 04:08:42,001 INFO : Inserting sp|P05160|F13B_HUMAN
12 May 2021 04:08:42,003 INFO : 47% Done
12 May 2021 04:08:42,010 INFO : 49% Done
12 May 2021 04:08:42,016 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:42,018 INFO : Inserting sp|P05452|TETN_HUMAN
12 May 2021 04:08:42,025 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,026 INFO : 50% Done
12 May 2021 04:08:42,028 INFO : Inserting sp|P07360|CO8G_HUMAN
12 May 2021 04:08:42,030 INFO : 51% Done
12 May 2021 04:08:42,035 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,037 INFO : Inserting sp|P08697|A2AP_HUMAN
12 May 2021 04:08:42,039 INFO : 52% Done
12 May 2021 04:08:42,046 INFO : 53% Done
12 May 2021 04:08:42,051 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:42,053 INFO : 54% Done
12 May 2021 04:08:42,055 INFO : Inserting sp|P13671|CO6_HUMAN
12 May 2021 04:08:42,061 INFO : 55% Done
12 May 2021 04:08:42,066 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:42,068 INFO : Inserting sp|P51884|LUM_HUMAN
12 May 2021 04:08:42,070 INFO : 57% Done
12 May 2021 04:08:42,081 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:42,083 INFO : Inserting sp|P80108|PHLD_HUMAN
12 May 2021 04:08:42,084 INFO : 59% Done
12 May 2021 04:08:42,090 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,092 INFO : Inserting sp|Q04756|HGFA_HUMAN
12 May 2021 04:08:42,094 INFO : 60% Done
12 May 2021 04:08:42,099 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,101 INFO : Inserting sp|Q14624|ITIH4_HUMAN
12 May 2021 04:08:42,103 INFO : 61% Done
12 May 2021 04:08:42,111 INFO : 62% Done
12 May 2021 04:08:42,116 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:42,118 INFO : Inserting sp|P00734|THRB_HUMAN
12 May 2021 04:08:42,120 INFO : 64% Done
12 May 2021 04:08:42,129 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,131 INFO : Inserting sp|P01008|ANT3_HUMAN
12 May 2021 04:08:42,134 INFO : 66% Done
12 May 2021 04:08:42,141 INFO : 67% Done
12 May 2021 04:08:42,172 DEBUG: Total peptides inserted: 3
12 May 2021 04:08:42,175 INFO : 68% Done
12 May 2021 04:08:42,178 INFO : Inserting sp|P02671|FIBA_HUMAN
12 May 2021 04:08:42,180 INFO : 69% Done
12 May 2021 04:08:42,189 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,191 INFO : Inserting sp|P02790|HEMO_HUMAN
12 May 2021 04:08:42,194 INFO : 70% Done
12 May 2021 04:08:42,202 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,204 INFO : Inserting sp|P04196|HRG_HUMAN
12 May 2021 04:08:42,207 INFO : 71% Done
12 May 2021 04:08:42,215 INFO : 72% Done
12 May 2021 04:08:42,222 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:42,224 INFO : Inserting sp|P04264|K2C1_HUMAN
12 May 2021 04:08:42,227 INFO : 74% Done
12 May 2021 04:08:42,234 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,236 INFO : Inserting sp|P05546|HEP2_HUMAN
12 May 2021 04:08:42,243 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,246 INFO : Inserting sp|P07357|CO8A_HUMAN
12 May 2021 04:08:42,248 INFO : 75% Done
12 May 2021 04:08:42,257 INFO : 76% Done
12 May 2021 04:08:42,263 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:42,265 INFO : Inserting sp|P20851|C4BPB_HUMAN
12 May 2021 04:08:42,267 INFO : 77% Done
12 May 2021 04:08:42,275 INFO : 78% Done
12 May 2021 04:08:42,283 INFO : 79% Done
12 May 2021 04:08:42,289 DEBUG: Total peptides inserted: 3
12 May 2021 04:08:42,291 INFO : Inserting sp|O75882|ATRN_HUMAN
12 May 2021 04:08:42,293 INFO : 81% Done
12 May 2021 04:08:42,299 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,302 INFO : Inserting sp|P00742|FA10_HUMAN
12 May 2021 04:08:42,308 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,310 INFO : 82% Done
12 May 2021 04:08:42,312 INFO : Inserting sp|P04278|SHBG_HUMAN
12 May 2021 04:08:42,314 INFO : 83% Done
12 May 2021 04:08:42,319 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,322 INFO : Inserting sp|P07359|GP1BA_HUMAN
12 May 2021 04:08:42,325 INFO : 84% Done
12 May 2021 04:08:42,331 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,333 INFO : Inserting sp|P08571|CD14_HUMAN
12 May 2021 04:08:42,335 INFO : 85% Done
12 May 2021 04:08:42,341 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,342 INFO : 86% Done
12 May 2021 04:08:42,344 INFO : Inserting sp|P13598|ICAM2_HUMAN
12 May 2021 04:08:42,346 INFO : 87% Done
12 May 2021 04:08:42,352 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,354 INFO : Inserting sp|P19823|ITIH2_HUMAN
12 May 2021 04:08:42,356 INFO : 88% Done
12 May 2021 04:08:42,362 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,364 INFO : Inserting sp|P20742|PZP_HUMAN
12 May 2021 04:08:42,366 INFO : 89% Done
12 May 2021 04:08:42,373 INFO : 90% Done
12 May 2021 04:08:42,378 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:42,380 INFO : Inserting sp|P22792|CPN2_HUMAN
12 May 2021 04:08:42,382 INFO : 92% Done
12 May 2021 04:08:42,387 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,388 INFO : Inserting sp|P27169|PON1_HUMAN
12 May 2021 04:08:42,394 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,396 INFO : 93% Done
12 May 2021 04:08:42,397 INFO : Inserting sp|P29622|KAIN_HUMAN
12 May 2021 04:08:42,399 INFO : 94% Done
12 May 2021 04:08:42,406 DEBUG: Total peptides inserted: 1
12 May 2021 04:08:42,411 INFO : Inserting sp|P43652|AFAM_HUMAN
12 May 2021 04:08:42,413 INFO : 95% Done
12 May 2021 04:08:42,425 INFO : 96% Done
12 May 2021 04:08:42,434 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:42,436 INFO : 97% Done
12 May 2021 04:08:42,441 INFO : Inserting sp|Q06033|ITIH3_HUMAN
12 May 2021 04:08:42,452 INFO : 98% Done
12 May 2021 04:08:42,461 DEBUG: Total peptides inserted: 2
12 May 2021 04:08:42,463 INFO : Done parsing Skyline document.
12 May 2021 04:08:42,613 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:08:42,686 INFO : Failed to complete task 'org.labkey.targetedms.pipeline.TargetedMSImportTask'
12 May 2021 04:08:42,689 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