12 May 2021 04:20:32,886 INFO : Starting to run task 'org.labkey.targetedms.pipeline.TargetedMSImportTask' at location 'webserver-high-priority'
12 May 2021 04:20:32,893 INFO : Starting to import Skyline document from 210512_GluC_P100_upload_2021-05-12_13-20-47.sky.zip
12 May 2021 04:20:32,893 INFO : Expanding GluC_P100_CE.optdb
12 May 2021 04:20:32,900 INFO : Expanding P100MM4_GluC_Spectrallibrary.blib
12 May 2021 04:20:32,905 INFO : Expanding P100MM3_GluC_Spectrallibrary.blib
12 May 2021 04:20:32,907 INFO : Expanding P100MM2_GluC_Spectrallibrary.blib
12 May 2021 04:20:32,909 INFO : Expanding P100MM1_GluC_Spectrallibrary.blib
12 May 2021 04:20:32,911 INFO : Expanding 210512_GluC_P100_upload.sky.view
12 May 2021 04:20:32,914 INFO : Expanding 210512_GluC_P100_upload.sky
12 May 2021 04:20:32,919 INFO : Expanding 210512_GluC_P100_upload.skyl
12 May 2021 04:20:32,941 INFO : 1% Done
12 May 2021 04:20:32,960 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-20-47/210512_GluC_P100_upload.skyd, unable to import chromatograms
12 May 2021 04:20:33,018 INFO : Inserting sp|P00738|HPT_HUMAN
12 May 2021 04:20:33,022 INFO : 3% Done
12 May 2021 04:20:33,037 INFO : 4% Done
12 May 2021 04:20:33,058 INFO : 7% Done
12 May 2021 04:20:33,072 DEBUG: Total peptides inserted: 3
12 May 2021 04:20:33,075 INFO : Inserting sp|P01009|A1AT_HUMAN
12 May 2021 04:20:33,078 INFO : 8% Done
12 May 2021 04:20:33,086 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,088 INFO : Inserting sp|P01011|AACT_HUMAN
12 May 2021 04:20:33,091 INFO : 9% Done
12 May 2021 04:20:33,100 INFO : 10% Done
12 May 2021 04:20:33,108 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,110 INFO : Inserting sp|P02647|APOA1_HUMAN
12 May 2021 04:20:33,112 INFO : 11% Done
12 May 2021 04:20:33,121 INFO : 13% Done
12 May 2021 04:20:33,135 INFO : 14% Done
12 May 2021 04:20:33,142 DEBUG: Total peptides inserted: 4
12 May 2021 04:20:33,143 INFO : 15% Done
12 May 2021 04:20:33,146 INFO : Inserting sp|P02679|FIBG_HUMAN
12 May 2021 04:20:33,147 INFO : 16% Done
12 May 2021 04:20:33,155 INFO : 18% Done
12 May 2021 04:20:33,167 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,169 INFO : Inserting sp|P02765|FETUA_HUMAN
12 May 2021 04:20:33,171 INFO : 19% Done
12 May 2021 04:20:33,178 INFO : 20% Done
12 May 2021 04:20:33,184 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,186 INFO : Inserting sp|P02774|VTDB_HUMAN
12 May 2021 04:20:33,188 INFO : 21% Done
12 May 2021 04:20:33,195 INFO : 22% Done
12 May 2021 04:20:33,201 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,202 INFO : Inserting sp|P05090|APOD_HUMAN
12 May 2021 04:20:33,204 INFO : 24% Done
12 May 2021 04:20:33,211 INFO : 25% Done
12 May 2021 04:20:33,224 INFO : 26% Done
12 May 2021 04:20:33,230 DEBUG: Total peptides inserted: 4
12 May 2021 04:20:33,232 INFO : Inserting sp|P06727|APOA4_HUMAN
12 May 2021 04:20:33,234 INFO : 27% Done
12 May 2021 04:20:33,241 INFO : 28% Done
12 May 2021 04:20:33,254 INFO : 29% Done
12 May 2021 04:20:33,265 INFO : 30% Done
12 May 2021 04:20:33,274 INFO : 31% Done
12 May 2021 04:20:33,282 DEBUG: Total peptides inserted: 5
12 May 2021 04:20:33,285 INFO : Inserting sp|P18428|LBP_HUMAN
12 May 2021 04:20:33,287 INFO : 32% Done
12 May 2021 04:20:33,295 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,297 INFO : Inserting sp|Q9NQ79|CRAC1_HUMAN
12 May 2021 04:20:33,300 INFO : 33% Done
12 May 2021 04:20:33,307 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,309 INFO : 34% Done
12 May 2021 04:20:33,312 INFO : Inserting sp|O14791|APOL1_HUMAN
12 May 2021 04:20:33,314 INFO : 35% Done
12 May 2021 04:20:33,320 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,323 INFO : Inserting sp|O43866|CD5L_HUMAN
12 May 2021 04:20:33,325 INFO : 36% Done
12 May 2021 04:20:33,331 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,333 INFO : Inserting sp|P00747|PLMN_HUMAN
12 May 2021 04:20:33,337 INFO : 38% Done
12 May 2021 04:20:33,344 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,346 INFO : Inserting sp|P00751|CFAB_HUMAN
12 May 2021 04:20:33,352 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,354 INFO : 39% Done
12 May 2021 04:20:33,356 INFO : Inserting sp|P01591|IGJ_HUMAN
12 May 2021 04:20:33,358 INFO : 40% Done
12 May 2021 04:20:33,366 INFO : 41% Done
12 May 2021 04:20:33,372 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,374 INFO : Inserting sp|P04003|C4BPA_HUMAN
12 May 2021 04:20:33,376 INFO : 42% Done
12 May 2021 04:20:33,384 INFO : 44% Done
12 May 2021 04:20:33,395 DEBUG: Total peptides inserted: 3
12 May 2021 04:20:33,397 INFO : Inserting sp|P05160|F13B_HUMAN
12 May 2021 04:20:33,399 INFO : 46% Done
12 May 2021 04:20:33,406 INFO : 47% Done
12 May 2021 04:20:33,411 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,413 INFO : Inserting sp|P05452|TETN_HUMAN
12 May 2021 04:20:33,416 INFO : 48% Done
12 May 2021 04:20:33,422 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,423 INFO : Inserting sp|P07360|CO8G_HUMAN
12 May 2021 04:20:33,425 INFO : 49% Done
12 May 2021 04:20:33,432 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,434 INFO : 50% Done
12 May 2021 04:20:33,435 INFO : Inserting sp|P08697|A2AP_HUMAN
12 May 2021 04:20:33,443 INFO : 51% Done
12 May 2021 04:20:33,448 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,450 INFO : 52% Done
12 May 2021 04:20:33,452 INFO : Inserting sp|P13671|CO6_HUMAN
12 May 2021 04:20:33,454 INFO : 53% Done
12 May 2021 04:20:33,464 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,465 INFO : 54% Done
12 May 2021 04:20:33,467 INFO : Inserting sp|P51884|LUM_HUMAN
12 May 2021 04:20:33,469 INFO : 55% Done
12 May 2021 04:20:33,481 INFO : 56% Done
12 May 2021 04:20:33,492 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,497 INFO : Inserting sp|P80108|PHLD_HUMAN
12 May 2021 04:20:33,500 INFO : 57% Done
12 May 2021 04:20:33,511 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,514 INFO : 58% Done
12 May 2021 04:20:33,518 INFO : Inserting sp|Q04756|HGFA_HUMAN
12 May 2021 04:20:33,522 INFO : 59% Done
12 May 2021 04:20:33,532 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,536 INFO : Inserting sp|Q14624|ITIH4_HUMAN
12 May 2021 04:20:33,539 INFO : 60% Done
12 May 2021 04:20:33,551 INFO : 61% Done
12 May 2021 04:20:33,560 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,562 INFO : 62% Done
12 May 2021 04:20:33,566 INFO : Inserting sp|P00734|THRB_HUMAN
12 May 2021 04:20:33,568 INFO : 63% Done
12 May 2021 04:20:33,583 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,585 INFO : 64% Done
12 May 2021 04:20:33,588 INFO : Inserting sp|P01008|ANT3_HUMAN
12 May 2021 04:20:33,590 INFO : 65% Done
12 May 2021 04:20:33,608 INFO : 67% Done
12 May 2021 04:20:33,615 DEBUG: Total peptides inserted: 3
12 May 2021 04:20:33,618 INFO : Inserting sp|P02671|FIBA_HUMAN
12 May 2021 04:20:33,621 INFO : 68% Done
12 May 2021 04:20:33,628 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,631 INFO : Inserting sp|P02790|HEMO_HUMAN
12 May 2021 04:20:33,633 INFO : 69% Done
12 May 2021 04:20:33,640 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,643 INFO : Inserting sp|P04196|HRG_HUMAN
12 May 2021 04:20:33,646 INFO : 70% Done
12 May 2021 04:20:33,654 INFO : 71% Done
12 May 2021 04:20:33,660 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,662 INFO : 72% Done
12 May 2021 04:20:33,664 INFO : Inserting sp|P04264|K2C1_HUMAN
12 May 2021 04:20:33,666 INFO : 73% Done
12 May 2021 04:20:33,673 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,675 INFO : Inserting sp|P05546|HEP2_HUMAN
12 May 2021 04:20:33,678 INFO : 74% Done
12 May 2021 04:20:33,684 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,686 INFO : Inserting sp|P07357|CO8A_HUMAN
12 May 2021 04:20:33,695 INFO : 75% Done
12 May 2021 04:20:33,701 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,703 INFO : Inserting sp|P20851|C4BPB_HUMAN
12 May 2021 04:20:33,705 INFO : 76% Done
12 May 2021 04:20:33,713 INFO : 78% Done
12 May 2021 04:20:33,724 DEBUG: Total peptides inserted: 3
12 May 2021 04:20:33,726 INFO : 79% Done
12 May 2021 04:20:33,728 INFO : Inserting sp|O75882|ATRN_HUMAN
12 May 2021 04:20:33,730 INFO : 80% Done
12 May 2021 04:20:33,738 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,740 INFO : Inserting sp|P00742|FA10_HUMAN
12 May 2021 04:20:33,742 INFO : 81% Done
12 May 2021 04:20:33,788 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,791 INFO : Inserting sp|P04278|SHBG_HUMAN
12 May 2021 04:20:33,795 INFO : 83% Done
12 May 2021 04:20:33,805 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,808 INFO : Inserting sp|P07359|GP1BA_HUMAN
12 May 2021 04:20:33,812 INFO : 84% Done
12 May 2021 04:20:33,821 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,824 INFO : Inserting sp|P08571|CD14_HUMAN
12 May 2021 04:20:33,828 INFO : 85% Done
12 May 2021 04:20:33,837 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,840 INFO : Inserting sp|P13598|ICAM2_HUMAN
12 May 2021 04:20:33,842 INFO : 86% Done
12 May 2021 04:20:33,851 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,854 INFO : 87% Done
12 May 2021 04:20:33,856 INFO : Inserting sp|P19823|ITIH2_HUMAN
12 May 2021 04:20:33,865 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,868 INFO : 88% Done
12 May 2021 04:20:33,870 INFO : Inserting sp|P20742|PZP_HUMAN
12 May 2021 04:20:33,873 INFO : 89% Done
12 May 2021 04:20:33,883 INFO : 90% Done
12 May 2021 04:20:33,890 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,892 INFO : Inserting sp|P22792|CPN2_HUMAN
12 May 2021 04:20:33,895 INFO : 91% Done
12 May 2021 04:20:33,901 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,903 INFO : Inserting sp|P27169|PON1_HUMAN
12 May 2021 04:20:33,906 INFO : 93% Done
12 May 2021 04:20:33,913 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,915 INFO : Inserting sp|P29622|KAIN_HUMAN
12 May 2021 04:20:33,923 DEBUG: Total peptides inserted: 1
12 May 2021 04:20:33,925 INFO : 94% Done
12 May 2021 04:20:33,927 INFO : Inserting sp|P43652|AFAM_HUMAN
12 May 2021 04:20:33,929 INFO : 95% Done
12 May 2021 04:20:33,937 INFO : 96% Done
12 May 2021 04:20:33,943 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,945 INFO : Inserting sp|Q06033|ITIH3_HUMAN
12 May 2021 04:20:33,947 INFO : 97% Done
12 May 2021 04:20:33,954 INFO : 98% Done
12 May 2021 04:20:33,961 DEBUG: Total peptides inserted: 2
12 May 2021 04:20:33,964 INFO : Done parsing Skyline document.
12 May 2021 04:20:34,078 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:34,114 INFO : Failed to complete task 'org.labkey.targetedms.pipeline.TargetedMSImportTask'
12 May 2021 04:20:34,116 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