Recurrent errors in database on vm schedules

[KuasarCloud]

Hey community!

After creating a schedule to start/stop vm_instances, a recurrent error appears in logs

025-07-17 11:29:19,383 ERROR [o.a.c.v.s.d.VMScheduledJobDaoImpl] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) DB Exception on: HikariProxyPreparedStatement@614529765 wrapping com.mysql.cj.jdbc.ServerPreparedStatement[6379]: INSERT INTO vm_scheduled_job (vm_scheduled_job.uuid, vm_scheduled_job.vm_id, vm_scheduled_job.vm_schedule_id, vm_scheduled_job.async_job_id, vm_scheduled_job.action, vm_scheduled_job.scheduled_timestamp) VALUES (x'65396330306236652d626463622d346430612d396162332d663466636136343536356130', 293, 120, NULL, 'STOP', '2025-07-18 04:00:00') java.sql.SQLIntegrityConstraintViolationException: Duplicate entry '120-2025-07-18 04:00:00' for key 'vm_schedule_id'

I have two management host running with ACS 4.20.1 with KVM Hypervisors. Any clue what is trying to insert it again in the database?

[DaanHoogland]

@KuasarCloud are there any debug messages above, especially with the same logid or ctx-.

[KuasarCloud]

Hi @DaanHoogland

this would be with the same ctx

2025-07-18 03:49:19,360 DEBUG [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) VM scheduler.poll is being called at 2025-07-18T08:49:00+0000
2025-07-18 03:49:19,370 ERROR [o.a.c.v.s.d.VMScheduledJobDaoImpl] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) DB Exception on: HikariProxyPreparedStatement@898825417 wrapping com.mysql.cj.jdbc.ServerPreparedStatement[18104]: INSERT INTO vm_scheduled_job (vm_scheduled_job.uuid, vm_scheduled_job.vm_id, vm_scheduled_job.vm_schedule_id, vm_scheduled_job.async_job_id, vm_scheduled_job.action, vm_scheduled_job.scheduled_timestamp) VALUES (x'34643731356134372d646163622d346534392d613466312d626663383834343337663336', 293, 118, NULL, 'START', '2025-07-18 11:00:00') java.sql.SQLIntegrityConstraintViolationException: Duplicate entry '118-2025-07-18 11:00:00' for key 'vm_schedule_id'
2025-07-18 03:49:19,371 DEBUG [c.c.u.d.T.Transaction] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) Rolling back the transaction: Time = 4 Name =  VMSchedulerPollTask; called by -TransactionLegacy.rollback:896-TransactionLegacy.removeUpTo:839-TransactionLegacy.close:663-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:175-ExposeInvocationInterceptor.invoke:97-ReflectiveMethodInvocation.proceed:186-JdkDynamicAopProxy.invoke:215-$Proxy373.persist:-1-VMSchedulerImpl.scheduleNextJob:167-VMSchedulerImpl.scheduleNextJobs:248-VMSchedulerImpl.poll:216
2025-07-18 03:49:19,373 DEBUG [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) Job is already scheduled.
2025-07-18 03:49:19,376 ERROR [o.a.c.v.s.d.VMScheduledJobDaoImpl] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) DB Exception on: HikariProxyPreparedStatement@2098749760 wrapping com.mysql.cj.jdbc.ServerPreparedStatement[18104]: INSERT INTO vm_scheduled_job (vm_scheduled_job.uuid, vm_scheduled_job.vm_id, vm_scheduled_job.vm_schedule_id, vm_scheduled_job.async_job_id, vm_scheduled_job.action, vm_scheduled_job.scheduled_timestamp) VALUES (x'62343238303963342d326435342d346432612d386662342d623138666632616661646465', 293, 120, NULL, 'STOP', '2025-07-19 04:00:00') java.sql.SQLIntegrityConstraintViolationException: Duplicate entry '120-2025-07-19 04:00:00' for key 'vm_schedule_id'
2025-07-18 03:49:19,377 DEBUG [c.c.u.d.T.Transaction] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) Rolling back the transaction: Time = 2 Name =  VMSchedulerPollTask; called by -TransactionLegacy.rollback:896-TransactionLegacy.removeUpTo:839-TransactionLegacy.close:663-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:175-ExposeInvocationInterceptor.invoke:97-ReflectiveMethodInvocation.proceed:186-JdkDynamicAopProxy.invoke:215-$Proxy373.persist:-1-VMSchedulerImpl.scheduleNextJob:167-VMSchedulerImpl.scheduleNextJobs:248-VMSchedulerImpl.poll:216
2025-07-18 03:49:19,379 DEBUG [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) Job is already scheduled.
2025-07-18 03:49:19,382 ERROR [o.a.c.v.s.d.VMScheduledJobDaoImpl] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) DB Exception on: HikariProxyPreparedStatement@1545630670 wrapping com.mysql.cj.jdbc.ServerPreparedStatement[18104]: INSERT INTO vm_scheduled_job (vm_scheduled_job.uuid, vm_scheduled_job.vm_id, vm_scheduled_job.vm_schedule_id, vm_scheduled_job.async_job_id, vm_scheduled_job.action, vm_scheduled_job.scheduled_timestamp) VALUES (x'39613738316263302d653064612d343639352d383639622d333434666338633134343861', 654, 122, NULL, 'START', '2025-07-18 11:00:00') java.sql.SQLIntegrityConstraintViolationException: Duplicate entry '122-2025-07-18 11:00:00' for key 'vm_schedule_id'
2025-07-18 03:49:19,383 DEBUG [c.c.u.d.T.Transaction] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) Rolling back the transaction: Time = 2 Name =  VMSchedulerPollTask; called by -TransactionLegacy.rollback:896-TransactionLegacy.removeUpTo:839-TransactionLegacy.close:663-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:175-ExposeInvocationInterceptor.invoke:97-ReflectiveMethodInvocation.proceed:186-JdkDynamicAopProxy.invoke:215-$Proxy373.persist:-1-VMSchedulerImpl.scheduleNextJob:167-VMSchedulerImpl.scheduleNextJobs:248-VMSchedulerImpl.poll:216
2025-07-18 03:49:19,384 DEBUG [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) Job is already scheduled.
2025-07-18 03:49:19,387 ERROR [o.a.c.v.s.d.VMScheduledJobDaoImpl] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) DB Exception on: HikariProxyPreparedStatement@1736698952 wrapping com.mysql.cj.jdbc.ServerPreparedStatement[18104]: INSERT INTO vm_scheduled_job (vm_scheduled_job.uuid, vm_scheduled_job.vm_id, vm_scheduled_job.vm_schedule_id, vm_scheduled_job.async_job_id, vm_scheduled_job.action, vm_scheduled_job.scheduled_timestamp) VALUES (x'34393765363563662d616635302d346666362d383736662d653239386563366164376330', 654, 124, NULL, 'STOP', '2025-07-19 04:00:00') java.sql.SQLIntegrityConstraintViolationException: Duplicate entry '124-2025-07-19 04:00:00' for key 'vm_schedule_id'
2025-07-18 03:49:19,390 DEBUG [c.c.u.d.T.Transaction] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) Rolling back the transaction: Time = 4 Name =  VMSchedulerPollTask; called by -TransactionLegacy.rollback:896-TransactionLegacy.removeUpTo:839-TransactionLegacy.close:663-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:175-ExposeInvocationInterceptor.invoke:97-ReflectiveMethodInvocation.proceed:186-JdkDynamicAopProxy.invoke:215-$Proxy373.persist:-1-VMSchedulerImpl.scheduleNextJob:167-VMSchedulerImpl.scheduleNextJobs:248-VMSchedulerImpl.poll:216
2025-07-18 03:49:19,392 DEBUG [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) Job is already scheduled.
2025-07-18 03:49:19,395 DEBUG [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) Got 0 scheduled jobs to be executed at 2025-07-18T08:49:00+0000
2025-07-18 03:49:19,399 INFO  [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-baef661e]) (logid:6169a69c) Cleaned up 0 VM scheduled job entries

[DaanHoogland]

This is not what I am asking for @KuasarCloud , please grep for logid:c3157b08 and for ctx-d11d1302 and look far any reason the attempt to add it again was made.

[KuasarCloud]

Hi @DaanHoogland

Please take a look, this all related to logid:c3157b08

2025-07-17 11:29:19,360 DEBUG [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) VM scheduler.poll is being called at 2025-07-17T16:29:00+0000
2025-07-17 11:29:19,376 ERROR [o.a.c.v.s.d.VMScheduledJobDaoImpl] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) DB Exception on: HikariProxyPreparedStatement@1276927238 wrapping com.mysql.cj.jdbc.ServerPreparedStatement[6379]: INSERT INTO vm_scheduled_job (vm_scheduled_job.uuid, vm_scheduled_job.vm_id, vm_scheduled_job.vm_schedule_id, vm_scheduled_job.async_job_id, vm_scheduled_job.action, vm_scheduled_job.scheduled_timestamp) VALUES (x'36383332303139372d343331622d343964652d393866622d333830313831333934653730', 293, 118, NULL, 'START', '2025-07-18 11:00:00') java.sql.SQLIntegrityConstraintViolationException: Duplicate entry '118-2025-07-18 11:00:00' for key 'vm_schedule_id'
2025-07-17 11:29:19,377 DEBUG [c.c.u.d.T.Transaction] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) Rolling back the transaction: Time = 3 Name =  VMSchedulerPollTask; called by -TransactionLegacy.rollback:896-TransactionLegacy.removeUpTo:839-TransactionLegacy.close:663-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:175-ExposeInvocationInterceptor.invoke:97-ReflectiveMethodInvocation.proceed:186-JdkDynamicAopProxy.invoke:215-$Proxy373.persist:-1-VMSchedulerImpl.scheduleNextJob:167-VMSchedulerImpl.scheduleNextJobs:248-VMSchedulerImpl.poll:216
2025-07-17 11:29:19,379 DEBUG [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) Job is already scheduled.
2025-07-17 11:29:19,383 ERROR [o.a.c.v.s.d.VMScheduledJobDaoImpl] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) DB Exception on: HikariProxyPreparedStatement@614529765 wrapping com.mysql.cj.jdbc.ServerPreparedStatement[6379]: INSERT INTO vm_scheduled_job (vm_scheduled_job.uuid, vm_scheduled_job.vm_id, vm_scheduled_job.vm_schedule_id, vm_scheduled_job.async_job_id, vm_scheduled_job.action, vm_scheduled_job.scheduled_timestamp) VALUES (x'65396330306236652d626463622d346430612d396162332d663466636136343536356130', 293, 120, NULL, 'STOP', '2025-07-18 04:00:00') java.sql.SQLIntegrityConstraintViolationException: Duplicate entry '120-2025-07-18 04:00:00' for key 'vm_schedule_id'
2025-07-17 11:29:19,383 DEBUG [c.c.u.d.T.Transaction] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) Rolling back the transaction: Time = 2 Name =  VMSchedulerPollTask; called by -TransactionLegacy.rollback:896-TransactionLegacy.removeUpTo:839-TransactionLegacy.close:663-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:175-ExposeInvocationInterceptor.invoke:97-ReflectiveMethodInvocation.proceed:186-JdkDynamicAopProxy.invoke:215-$Proxy373.persist:-1-VMSchedulerImpl.scheduleNextJob:167-VMSchedulerImpl.scheduleNextJobs:248-VMSchedulerImpl.poll:216
2025-07-17 11:29:19,385 DEBUG [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) Job is already scheduled.
2025-07-17 11:29:19,389 ERROR [o.a.c.v.s.d.VMScheduledJobDaoImpl] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) DB Exception on: HikariProxyPreparedStatement@1815803217 wrapping com.mysql.cj.jdbc.ServerPreparedStatement[6379]: INSERT INTO vm_scheduled_job (vm_scheduled_job.uuid, vm_scheduled_job.vm_id, vm_scheduled_job.vm_schedule_id, vm_scheduled_job.async_job_id, vm_scheduled_job.action, vm_scheduled_job.scheduled_timestamp) VALUES (x'30643861656165632d343234342d343835382d386363662d366161393337613734383536', 654, 122, NULL, 'START', '2025-07-18 11:00:00') java.sql.SQLIntegrityConstraintViolationException: Duplicate entry '122-2025-07-18 11:00:00' for key 'vm_schedule_id'
2025-07-17 11:29:19,389 DEBUG [c.c.u.d.T.Transaction] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) Rolling back the transaction: Time = 2 Name =  VMSchedulerPollTask; called by -TransactionLegacy.rollback:896-TransactionLegacy.removeUpTo:839-TransactionLegacy.close:663-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:175-ExposeInvocationInterceptor.invoke:97-ReflectiveMethodInvocation.proceed:186-JdkDynamicAopProxy.invoke:215-$Proxy373.persist:-1-VMSchedulerImpl.scheduleNextJob:167-VMSchedulerImpl.scheduleNextJobs:248-VMSchedulerImpl.poll:216
2025-07-17 11:29:19,391 DEBUG [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) Job is already scheduled.
2025-07-17 11:29:19,395 ERROR [o.a.c.v.s.d.VMScheduledJobDaoImpl] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) DB Exception on: HikariProxyPreparedStatement@1276268827 wrapping com.mysql.cj.jdbc.ServerPreparedStatement[6379]: INSERT INTO vm_scheduled_job (vm_scheduled_job.uuid, vm_scheduled_job.vm_id, vm_scheduled_job.vm_schedule_id, vm_scheduled_job.async_job_id, vm_scheduled_job.action, vm_scheduled_job.scheduled_timestamp) VALUES (x'64313833353966382d333764322d343836632d383138632d356263663666393134303937', 654, 124, NULL, 'STOP', '2025-07-18 04:00:00') java.sql.SQLIntegrityConstraintViolationException: Duplicate entry '124-2025-07-18 04:00:00' for key 'vm_schedule_id'
2025-07-17 11:29:19,396 DEBUG [c.c.u.d.T.Transaction] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) Rolling back the transaction: Time = 3 Name =  VMSchedulerPollTask; called by -TransactionLegacy.rollback:896-TransactionLegacy.removeUpTo:839-TransactionLegacy.close:663-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:175-ExposeInvocationInterceptor.invoke:97-ReflectiveMethodInvocation.proceed:186-JdkDynamicAopProxy.invoke:215-$Proxy373.persist:-1-VMSchedulerImpl.scheduleNextJob:167-VMSchedulerImpl.scheduleNextJobs:248-VMSchedulerImpl.poll:216
2025-07-17 11:29:19,398 DEBUG [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) Job is already scheduled.
2025-07-17 11:29:19,401 DEBUG [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) Got 0 scheduled jobs to be executed at 2025-07-17T16:29:00+0000
2025-07-17 11:29:19,404 INFO  [o.a.c.v.s.VMSchedulerImpl] (VMSchedulerPollTask:[ctx-d11d1302]) (logid:c3157b08) Cleaned up 0 VM scheduled job entries

[DaanHoogland]

Sorry @KuasarCloud , there is not enough information there to make even a guess. You will have to investigate the logs more.

[KuasarCloud]

It appears to be a race condition error caused by multiple scheduler instances running concurrently. We have two ACS Server Manager nodes, and when a scheduled task is created on one node, the other node throws an error — and the same happens in reverse.

[DaanHoogland]

@KuasarCloud , thanks for investigating.

So you are saying that both MS are trying to update the same schedule, by creating the same task?

If so that seems a bug to me (or at least an improvement waiting for implementation ;) The scheduler should recognise that no work needs to done. One more question; Do these errors keep coming or do they stop after a couple of retries?

Can you provide a short description of the scenario and the excerpts from the logs of both MSses in a new issue?

[KuasarCloud]

Hi @DaanHoogland, issue created at #11564 and to answer your question, it keeps going forever, the only way to stop it is eliminating the rule

[weizhouapache]

thanks @KuasarCloud
closing this