12 May 2021 04:05:39,614 INFO : Starting to run task 'org.labkey.targetedms.pipeline.TargetedMSImportTask' at location 'webserver-high-priority' 12 May 2021 04:05:39,621 INFO : Starting to import Skyline document from 210512_GluC_P100_upload_2021-05-12_13-05-17.sky.zip 12 May 2021 04:05:39,622 INFO : Expanding 210203_HumanProteomeUniprot.protdb 12 May 2021 04:05:42,271 INFO : Expanding GluC_P100_CE.optdb 12 May 2021 04:05:42,275 INFO : Expanding P100MM4_GluC_Spectrallibrary.blib 12 May 2021 04:05:42,277 INFO : Expanding P100MM1_GluC_Spectrallibrary.blib 12 May 2021 04:05:42,282 INFO : Expanding P100MM2_GluC_Spectrallibrary.blib 12 May 2021 04:05:42,284 INFO : Expanding P100MM3_GluC_Spectrallibrary.blib 12 May 2021 04:05:42,419 INFO : Expanding 210512_GluC_P100_upload.sky.view 12 May 2021 04:05:42,445 INFO : Expanding 210512_GluC_P100_upload.sky 12 May 2021 04:05:42,451 INFO : Expanding 210512_GluC_P100_upload.skyl 12 May 2021 04:05:42,469 INFO : 1% Done 12 May 2021 04:05:42,495 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-05-17/210512_GluC_P100_upload.skyd, unable to import chromatograms 12 May 2021 04:05:42,557 INFO : Inserting QTag 12 May 2021 04:05:42,562 INFO : 2% Done 12 May 2021 04:05:42,575 INFO : 3% Done 12 May 2021 04:05:42,584 INFO : 4% Done 12 May 2021 04:05:42,600 INFO : 5% Done 12 May 2021 04:05:42,606 DEBUG: Total peptides inserted: 5 12 May 2021 04:05:42,612 INFO : Inserting sp|P00738|HPT_HUMAN 12 May 2021 04:05:42,615 INFO : 6% Done 12 May 2021 04:05:42,626 INFO : 8% Done 12 May 2021 04:05:42,649 INFO : 10% Done 12 May 2021 04:05:42,664 DEBUG: Total peptides inserted: 3 12 May 2021 04:05:42,669 INFO : Inserting sp|P01009|A1AT_HUMAN 12 May 2021 04:05:42,672 INFO : 11% Done 12 May 2021 04:05:42,681 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:42,683 INFO : 12% Done 12 May 2021 04:05:42,688 INFO : Inserting sp|P01011|AACT_HUMAN 12 May 2021 04:05:42,699 INFO : 13% Done 12 May 2021 04:05:42,707 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:42,709 INFO : 14% Done 12 May 2021 04:05:42,713 INFO : Inserting sp|P02647|APOA1_HUMAN 12 May 2021 04:05:42,723 INFO : 15% Done 12 May 2021 04:05:42,732 INFO : 17% Done 12 May 2021 04:05:42,745 DEBUG: Total peptides inserted: 4 12 May 2021 04:05:42,749 INFO : Inserting sp|P02679|FIBG_HUMAN 12 May 2021 04:05:42,752 INFO : 19% Done 12 May 2021 04:05:42,761 INFO : 20% Done 12 May 2021 04:05:42,773 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:42,775 INFO : 21% Done 12 May 2021 04:05:42,777 INFO : Inserting sp|P02765|FETUA_HUMAN 12 May 2021 04:05:42,780 INFO : 22% Done 12 May 2021 04:05:42,796 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:42,798 INFO : 23% Done 12 May 2021 04:05:42,801 INFO : Inserting sp|P02774|VTDB_HUMAN 12 May 2021 04:05:42,802 INFO : 24% Done 12 May 2021 04:05:42,810 INFO : 25% Done 12 May 2021 04:05:42,817 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:42,820 INFO : Inserting sp|P05090|APOD_HUMAN 12 May 2021 04:05:42,828 INFO : 26% Done 12 May 2021 04:05:42,835 INFO : 27% Done 12 May 2021 04:05:42,843 INFO : 28% Done 12 May 2021 04:05:42,849 DEBUG: Total peptides inserted: 4 12 May 2021 04:05:42,850 INFO : 29% Done 12 May 2021 04:05:42,872 INFO : Inserting sp|P06727|APOA4_HUMAN 12 May 2021 04:05:42,882 INFO : 30% Done 12 May 2021 04:05:42,890 INFO : 31% Done 12 May 2021 04:05:42,898 INFO : 32% Done 12 May 2021 04:05:42,906 INFO : 34% Done 12 May 2021 04:05:42,912 DEBUG: Total peptides inserted: 5 12 May 2021 04:05:42,915 INFO : Inserting sp|P18428|LBP_HUMAN 12 May 2021 04:05:42,922 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:42,924 INFO : 35% Done 12 May 2021 04:05:42,927 INFO : Inserting sp|Q9NQ79|CRAC1_HUMAN 12 May 2021 04:05:42,929 INFO : 36% Done 12 May 2021 04:05:42,935 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:42,938 INFO : Inserting sp|O14791|APOL1_HUMAN 12 May 2021 04:05:42,940 INFO : 37% Done 12 May 2021 04:05:42,948 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:42,951 INFO : Inserting sp|O43866|CD5L_HUMAN 12 May 2021 04:05:42,954 INFO : 38% Done 12 May 2021 04:05:42,960 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:42,961 INFO : 39% Done 12 May 2021 04:05:42,964 INFO : Inserting sp|P00747|PLMN_HUMAN 12 May 2021 04:05:42,971 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:42,973 INFO : 40% Done 12 May 2021 04:05:42,975 INFO : Inserting sp|P00751|CFAB_HUMAN 12 May 2021 04:05:42,978 INFO : 41% Done 12 May 2021 04:05:42,990 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:42,993 INFO : Inserting sp|P01591|IGJ_HUMAN 12 May 2021 04:05:42,997 INFO : 42% Done 12 May 2021 04:05:43,010 INFO : 43% Done 12 May 2021 04:05:43,020 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:43,024 INFO : Inserting sp|P04003|C4BPA_HUMAN 12 May 2021 04:05:43,027 INFO : 44% Done 12 May 2021 04:05:43,038 INFO : 45% Done 12 May 2021 04:05:43,049 INFO : 46% Done 12 May 2021 04:05:43,057 DEBUG: Total peptides inserted: 3 12 May 2021 04:05:43,061 INFO : Inserting sp|P05160|F13B_HUMAN 12 May 2021 04:05:43,063 INFO : 47% Done 12 May 2021 04:05:43,073 INFO : 49% Done 12 May 2021 04:05:43,080 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:43,083 INFO : Inserting sp|P05452|TETN_HUMAN 12 May 2021 04:05:43,092 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,094 INFO : 50% Done 12 May 2021 04:05:43,097 INFO : Inserting sp|P07360|CO8G_HUMAN 12 May 2021 04:05:43,100 INFO : 51% Done 12 May 2021 04:05:43,107 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,111 INFO : Inserting sp|P08697|A2AP_HUMAN 12 May 2021 04:05:43,115 INFO : 52% Done 12 May 2021 04:05:43,130 INFO : 53% Done 12 May 2021 04:05:43,142 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:43,144 INFO : 54% Done 12 May 2021 04:05:43,149 INFO : Inserting sp|P13671|CO6_HUMAN 12 May 2021 04:05:43,161 INFO : 55% Done 12 May 2021 04:05:43,171 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:43,176 INFO : Inserting sp|P51884|LUM_HUMAN 12 May 2021 04:05:43,179 INFO : 57% Done 12 May 2021 04:05:43,200 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:43,206 INFO : Inserting sp|P80108|PHLD_HUMAN 12 May 2021 04:05:43,210 INFO : 59% Done 12 May 2021 04:05:43,222 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,227 INFO : Inserting sp|Q04756|HGFA_HUMAN 12 May 2021 04:05:43,230 INFO : 60% Done 12 May 2021 04:05:43,240 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,245 INFO : Inserting sp|Q14624|ITIH4_HUMAN 12 May 2021 04:05:43,248 INFO : 61% Done 12 May 2021 04:05:43,259 INFO : 62% Done 12 May 2021 04:05:43,268 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:43,272 INFO : Inserting sp|P00734|THRB_HUMAN 12 May 2021 04:05:43,275 INFO : 64% Done 12 May 2021 04:05:43,289 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,293 INFO : Inserting sp|P01008|ANT3_HUMAN 12 May 2021 04:05:43,296 INFO : 66% Done 12 May 2021 04:05:43,305 INFO : 67% Done 12 May 2021 04:05:43,320 DEBUG: Total peptides inserted: 3 12 May 2021 04:05:43,322 INFO : 68% Done 12 May 2021 04:05:43,326 INFO : Inserting sp|P02671|FIBA_HUMAN 12 May 2021 04:05:43,328 INFO : 69% Done 12 May 2021 04:05:43,335 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,338 INFO : Inserting sp|P02790|HEMO_HUMAN 12 May 2021 04:05:43,340 INFO : 70% Done 12 May 2021 04:05:43,347 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,350 INFO : Inserting sp|P04196|HRG_HUMAN 12 May 2021 04:05:43,352 INFO : 71% Done 12 May 2021 04:05:43,360 INFO : 72% Done 12 May 2021 04:05:43,366 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:43,370 INFO : Inserting sp|P04264|K2C1_HUMAN 12 May 2021 04:05:43,372 INFO : 74% Done 12 May 2021 04:05:43,379 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,384 INFO : Inserting sp|P05546|HEP2_HUMAN 12 May 2021 04:05:43,396 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,400 INFO : Inserting sp|P07357|CO8A_HUMAN 12 May 2021 04:05:43,404 INFO : 75% Done 12 May 2021 04:05:43,416 INFO : 76% Done 12 May 2021 04:05:43,424 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:43,428 INFO : Inserting sp|P20851|C4BPB_HUMAN 12 May 2021 04:05:43,430 INFO : 77% Done 12 May 2021 04:05:43,441 INFO : 78% Done 12 May 2021 04:05:43,451 INFO : 79% Done 12 May 2021 04:05:43,458 DEBUG: Total peptides inserted: 3 12 May 2021 04:05:43,462 INFO : Inserting sp|O75882|ATRN_HUMAN 12 May 2021 04:05:43,464 INFO : 81% Done 12 May 2021 04:05:43,472 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,475 INFO : Inserting sp|P00742|FA10_HUMAN 12 May 2021 04:05:43,484 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,485 INFO : 82% Done 12 May 2021 04:05:43,488 INFO : Inserting sp|P04278|SHBG_HUMAN 12 May 2021 04:05:43,490 INFO : 83% Done 12 May 2021 04:05:43,497 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,500 INFO : Inserting sp|P07359|GP1BA_HUMAN 12 May 2021 04:05:43,502 INFO : 84% Done 12 May 2021 04:05:43,509 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,512 INFO : Inserting sp|P08571|CD14_HUMAN 12 May 2021 04:05:43,514 INFO : 85% Done 12 May 2021 04:05:43,521 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,522 INFO : 86% Done 12 May 2021 04:05:43,525 INFO : Inserting sp|P13598|ICAM2_HUMAN 12 May 2021 04:05:43,527 INFO : 87% Done 12 May 2021 04:05:43,534 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,537 INFO : Inserting sp|P19823|ITIH2_HUMAN 12 May 2021 04:05:43,539 INFO : 88% Done 12 May 2021 04:05:43,546 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,549 INFO : Inserting sp|P20742|PZP_HUMAN 12 May 2021 04:05:43,551 INFO : 89% Done 12 May 2021 04:05:43,558 INFO : 90% Done 12 May 2021 04:05:43,566 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:43,569 INFO : Inserting sp|P22792|CPN2_HUMAN 12 May 2021 04:05:43,573 INFO : 92% Done 12 May 2021 04:05:43,580 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,584 INFO : Inserting sp|P27169|PON1_HUMAN 12 May 2021 04:05:43,592 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,595 INFO : 93% Done 12 May 2021 04:05:43,598 INFO : Inserting sp|P29622|KAIN_HUMAN 12 May 2021 04:05:43,601 INFO : 94% Done 12 May 2021 04:05:43,609 DEBUG: Total peptides inserted: 1 12 May 2021 04:05:43,612 INFO : Inserting sp|P43652|AFAM_HUMAN 12 May 2021 04:05:43,615 INFO : 95% Done 12 May 2021 04:05:43,625 INFO : 96% Done 12 May 2021 04:05:43,632 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:43,634 INFO : 97% Done 12 May 2021 04:05:43,638 INFO : Inserting sp|Q06033|ITIH3_HUMAN 12 May 2021 04:05:43,648 INFO : 98% Done 12 May 2021 04:05:43,656 DEBUG: Total peptides inserted: 2 12 May 2021 04:05:43,656 INFO : Done parsing Skyline document. 12 May 2021 04:05:43,866 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:05:43,929 INFO : Failed to complete task 'org.labkey.targetedms.pipeline.TargetedMSImportTask' 12 May 2021 04:05:43,931 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