12 May 2021 04:12:25,690 INFO : Starting to run task 'org.labkey.targetedms.pipeline.TargetedMSImportTask' at location 'webserver-high-priority'
12 May 2021 04:12:25,696 INFO : Starting to import Skyline document from 210512_GluC_P100_upload_2021-05-12_13-12-40.sky.zip
12 May 2021 04:12:25,697 INFO : Expanding GluC_P100_CE.optdb
12 May 2021 04:12:25,704 INFO : Expanding P100MM4_GluC_Spectrallibrary.blib
12 May 2021 04:12:25,708 INFO : Expanding P100MM3_GluC_Spectrallibrary.blib
12 May 2021 04:12:25,711 INFO : Expanding P100MM2_GluC_Spectrallibrary.blib
12 May 2021 04:12:25,713 INFO : Expanding P100MM1_GluC_Spectrallibrary.blib
12 May 2021 04:12:25,715 INFO : Expanding 210512_GluC_P100_upload.sky.view
12 May 2021 04:12:25,718 INFO : Expanding 210512_GluC_P100_upload.sky
12 May 2021 04:12:25,724 INFO : Expanding 210512_GluC_P100_upload.skyl
12 May 2021 04:12:25,739 INFO : 1% Done
12 May 2021 04:12:25,764 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-12-40/210512_GluC_P100_upload.skyd, unable to import chromatograms
12 May 2021 04:12:25,811 INFO : Inserting QTag
12 May 2021 04:12:25,814 INFO : 2% Done
12 May 2021 04:12:25,821 INFO : 3% Done
12 May 2021 04:12:25,827 INFO : 4% Done
12 May 2021 04:12:25,841 INFO : 5% Done
12 May 2021 04:12:25,845 DEBUG: Total peptides inserted: 5
12 May 2021 04:12:25,848 INFO : Inserting sp|P00738|HPT_HUMAN
12 May 2021 04:12:25,850 INFO : 6% Done
12 May 2021 04:12:25,860 INFO : 8% Done
12 May 2021 04:12:25,878 INFO : 10% Done
12 May 2021 04:12:25,892 DEBUG: Total peptides inserted: 3
12 May 2021 04:12:25,895 INFO : Inserting sp|P01009|A1AT_HUMAN
12 May 2021 04:12:25,897 INFO : 11% Done
12 May 2021 04:12:25,904 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:25,906 INFO : 12% Done
12 May 2021 04:12:25,908 INFO : Inserting sp|P01011|AACT_HUMAN
12 May 2021 04:12:25,917 INFO : 13% Done
12 May 2021 04:12:25,926 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:25,928 INFO : 14% Done
12 May 2021 04:12:25,931 INFO : Inserting sp|P02647|APOA1_HUMAN
12 May 2021 04:12:25,941 INFO : 15% Done
12 May 2021 04:12:25,951 INFO : 17% Done
12 May 2021 04:12:25,964 DEBUG: Total peptides inserted: 4
12 May 2021 04:12:25,966 INFO : Inserting sp|P02679|FIBG_HUMAN
12 May 2021 04:12:25,968 INFO : 19% Done
12 May 2021 04:12:25,976 INFO : 20% Done
12 May 2021 04:12:25,988 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:25,990 INFO : 21% Done
12 May 2021 04:12:25,992 INFO : Inserting sp|P02765|FETUA_HUMAN
12 May 2021 04:12:25,995 INFO : 22% Done
12 May 2021 04:12:26,007 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:26,009 INFO : 23% Done
12 May 2021 04:12:26,011 INFO : Inserting sp|P02774|VTDB_HUMAN
12 May 2021 04:12:26,013 INFO : 24% Done
12 May 2021 04:12:26,021 INFO : 25% Done
12 May 2021 04:12:26,027 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:26,029 INFO : Inserting sp|P05090|APOD_HUMAN
12 May 2021 04:12:26,038 INFO : 26% Done
12 May 2021 04:12:26,046 INFO : 27% Done
12 May 2021 04:12:26,054 INFO : 28% Done
12 May 2021 04:12:26,060 DEBUG: Total peptides inserted: 4
12 May 2021 04:12:26,062 INFO : 29% Done
12 May 2021 04:12:26,066 INFO : Inserting sp|P06727|APOA4_HUMAN
12 May 2021 04:12:26,075 INFO : 30% Done
12 May 2021 04:12:26,083 INFO : 31% Done
12 May 2021 04:12:26,090 INFO : 32% Done
12 May 2021 04:12:26,098 INFO : 34% Done
12 May 2021 04:12:26,104 DEBUG: Total peptides inserted: 5
12 May 2021 04:12:26,106 INFO : Inserting sp|P18428|LBP_HUMAN
12 May 2021 04:12:26,113 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,114 INFO : 35% Done
12 May 2021 04:12:26,116 INFO : Inserting sp|Q9NQ79|CRAC1_HUMAN
12 May 2021 04:12:26,118 INFO : 36% Done
12 May 2021 04:12:26,124 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,126 INFO : Inserting sp|O14791|APOL1_HUMAN
12 May 2021 04:12:26,128 INFO : 37% Done
12 May 2021 04:12:26,134 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,137 INFO : Inserting sp|O43866|CD5L_HUMAN
12 May 2021 04:12:26,138 INFO : 38% Done
12 May 2021 04:12:26,144 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,146 INFO : 39% Done
12 May 2021 04:12:26,148 INFO : Inserting sp|P00747|PLMN_HUMAN
12 May 2021 04:12:26,155 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,156 INFO : 40% Done
12 May 2021 04:12:26,158 INFO : Inserting sp|P00751|CFAB_HUMAN
12 May 2021 04:12:26,160 INFO : 41% Done
12 May 2021 04:12:26,166 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,168 INFO : Inserting sp|P01591|IGJ_HUMAN
12 May 2021 04:12:26,170 INFO : 42% Done
12 May 2021 04:12:26,178 INFO : 43% Done
12 May 2021 04:12:26,184 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:26,186 INFO : Inserting sp|P04003|C4BPA_HUMAN
12 May 2021 04:12:26,187 INFO : 44% Done
12 May 2021 04:12:26,195 INFO : 45% Done
12 May 2021 04:12:26,203 INFO : 47% Done
12 May 2021 04:12:26,209 DEBUG: Total peptides inserted: 3
12 May 2021 04:12:26,211 INFO : Inserting sp|P05160|F13B_HUMAN
12 May 2021 04:12:26,219 INFO : 49% Done
12 May 2021 04:12:26,225 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:26,227 INFO : Inserting sp|P05452|TETN_HUMAN
12 May 2021 04:12:26,234 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,235 INFO : 50% Done
12 May 2021 04:12:26,237 INFO : Inserting sp|P07360|CO8G_HUMAN
12 May 2021 04:12:26,239 INFO : 51% Done
12 May 2021 04:12:26,244 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,246 INFO : Inserting sp|P08697|A2AP_HUMAN
12 May 2021 04:12:26,248 INFO : 52% Done
12 May 2021 04:12:26,256 INFO : 53% Done
12 May 2021 04:12:26,262 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:26,264 INFO : Inserting sp|P13671|CO6_HUMAN
12 May 2021 04:12:26,266 INFO : 54% Done
12 May 2021 04:12:26,273 INFO : 55% Done
12 May 2021 04:12:26,279 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:26,281 INFO : Inserting sp|P51884|LUM_HUMAN
12 May 2021 04:12:26,282 INFO : 57% Done
12 May 2021 04:12:26,295 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:26,297 INFO : Inserting sp|P80108|PHLD_HUMAN
12 May 2021 04:12:26,299 INFO : 59% Done
12 May 2021 04:12:26,305 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,307 INFO : Inserting sp|Q04756|HGFA_HUMAN
12 May 2021 04:12:26,309 INFO : 60% Done
12 May 2021 04:12:26,315 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,317 INFO : Inserting sp|Q14624|ITIH4_HUMAN
12 May 2021 04:12:26,318 INFO : 61% Done
12 May 2021 04:12:26,326 INFO : 62% Done
12 May 2021 04:12:26,332 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:26,334 INFO : Inserting sp|P00734|THRB_HUMAN
12 May 2021 04:12:26,336 INFO : 65% Done
12 May 2021 04:12:26,347 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,349 INFO : Inserting sp|P01008|ANT3_HUMAN
12 May 2021 04:12:26,357 INFO : 67% Done
12 May 2021 04:12:26,370 DEBUG: Total peptides inserted: 3
12 May 2021 04:12:26,371 INFO : 68% Done
12 May 2021 04:12:26,373 INFO : Inserting sp|P02671|FIBA_HUMAN
12 May 2021 04:12:26,375 INFO : 69% Done
12 May 2021 04:12:26,381 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,384 INFO : Inserting sp|P02790|HEMO_HUMAN
12 May 2021 04:12:26,386 INFO : 70% Done
12 May 2021 04:12:26,392 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,394 INFO : Inserting sp|P04196|HRG_HUMAN
12 May 2021 04:12:26,396 INFO : 71% Done
12 May 2021 04:12:26,403 INFO : 72% Done
12 May 2021 04:12:26,409 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:26,411 INFO : Inserting sp|P04264|K2C1_HUMAN
12 May 2021 04:12:26,413 INFO : 74% Done
12 May 2021 04:12:26,422 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,427 INFO : Inserting sp|P05546|HEP2_HUMAN
12 May 2021 04:12:26,439 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,443 INFO : Inserting sp|P07357|CO8A_HUMAN
12 May 2021 04:12:26,446 INFO : 75% Done
12 May 2021 04:12:26,458 INFO : 76% Done
12 May 2021 04:12:26,465 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:26,468 INFO : Inserting sp|P20851|C4BPB_HUMAN
12 May 2021 04:12:26,470 INFO : 77% Done
12 May 2021 04:12:26,480 INFO : 78% Done
12 May 2021 04:12:26,489 INFO : 79% Done
12 May 2021 04:12:26,496 DEBUG: Total peptides inserted: 3
12 May 2021 04:12:26,499 INFO : Inserting sp|O75882|ATRN_HUMAN
12 May 2021 04:12:26,501 INFO : 81% Done
12 May 2021 04:12:26,508 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,510 INFO : Inserting sp|P00742|FA10_HUMAN
12 May 2021 04:12:26,512 INFO : 82% Done
12 May 2021 04:12:26,519 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,521 INFO : Inserting sp|P04278|SHBG_HUMAN
12 May 2021 04:12:26,523 INFO : 83% Done
12 May 2021 04:12:26,529 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,531 INFO : Inserting sp|P07359|GP1BA_HUMAN
12 May 2021 04:12:26,533 INFO : 84% Done
12 May 2021 04:12:26,540 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,542 INFO : Inserting sp|P08571|CD14_HUMAN
12 May 2021 04:12:26,544 INFO : 85% Done
12 May 2021 04:12:26,550 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,551 INFO : 86% Done
12 May 2021 04:12:26,554 INFO : Inserting sp|P13598|ICAM2_HUMAN
12 May 2021 04:12:26,555 INFO : 87% Done
12 May 2021 04:12:26,562 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,564 INFO : Inserting sp|P19823|ITIH2_HUMAN
12 May 2021 04:12:26,566 INFO : 88% Done
12 May 2021 04:12:26,572 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,574 INFO : Inserting sp|P20742|PZP_HUMAN
12 May 2021 04:12:26,576 INFO : 89% Done
12 May 2021 04:12:26,583 INFO : 90% Done
12 May 2021 04:12:26,589 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:26,591 INFO : Inserting sp|P22792|CPN2_HUMAN
12 May 2021 04:12:26,592 INFO : 92% Done
12 May 2021 04:12:26,598 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,600 INFO : Inserting sp|P27169|PON1_HUMAN
12 May 2021 04:12:26,606 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,608 INFO : 93% Done
12 May 2021 04:12:26,610 INFO : Inserting sp|P29622|KAIN_HUMAN
12 May 2021 04:12:26,611 INFO : 94% Done
12 May 2021 04:12:26,617 DEBUG: Total peptides inserted: 1
12 May 2021 04:12:26,619 INFO : Inserting sp|P43652|AFAM_HUMAN
12 May 2021 04:12:26,621 INFO : 95% Done
12 May 2021 04:12:26,627 INFO : 96% Done
12 May 2021 04:12:26,634 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:26,635 INFO : 97% Done
12 May 2021 04:12:26,637 INFO : Inserting sp|Q06033|ITIH3_HUMAN
12 May 2021 04:12:26,647 INFO : 98% Done
12 May 2021 04:12:26,654 DEBUG: Total peptides inserted: 2
12 May 2021 04:12:26,655 INFO : Done parsing Skyline document.
12 May 2021 04:12:26,758 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:12:26,773 INFO : Failed to complete task 'org.labkey.targetedms.pipeline.TargetedMSImportTask'
12 May 2021 04:12:26,774 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