search

alfio-event / alf.io

alf.io - The open source ticket reservation system for conferences, trade shows, workshops, meetups
https://alf.io
GNU General Public License v3.0
1.38k stars 344 forks source link

cleanupExpiredPendingReservation - ERROR: update or delete on table "tickets_reservation" violates foreign key constraint "ticket_tickets_reservation_id_fkey" on table "ticket" #848

Open icougil opened 4 years ago

icougil commented 4 years ago

Describe the bug It seems that the cleanupExpiredPendingReservation is failing trying to cleaning up some not finished reservations.

To Reproduce Don't know how to reproduce it, sorry 😅

Expected behavior What we should expect is probably let the job continue and not fail, because starting from then, all the "pending" Reservations are not going to be cancelled and they will remain forever in the system.

Screenshots image

Stacktrace 

rg.springframework.dao.DataIntegrityViolationException: PreparedStatementCallback; SQL [delete from tickets_reservation where id in (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)]; ERROR: update or delete on table "tickets_reservation" violates foreign key constraint "ticket_tickets_reservation_id_fkey" on table "ticket"
2019-12-11T23:41:14+01:00 22:41:14.081 [scheduling-1] ERROR org.springframework.scheduling.support.TaskUtils$LoggingErrorHandler - Unexpected error occurred in scheduled task.
2019-12-11T23:41:14+01:00 at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:246) ~[spring-jdbc-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72) ~[spring-jdbc-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 Detail: Key is still referenced from table "ticket".; nested exception is org.postgresql.util.PSQLException: ERROR: update or delete on table "tickets_reservation" violates foreign key constraint "ticket_tickets_reservation_id_fkey" on table "ticket"
2019-12-11T23:41:14+01:00 Detail: Key is still referenced from table "ticket".
2019-12-11T23:41:14+01:00 at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:632) ~[spring-jdbc-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1442) ~[spring-jdbc-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:861) ~[spring-jdbc-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:882) ~[spring-jdbc-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at com.sun.proxy.$Proxy89.remove(Unknown Source) ~[?:?]
2019-12-11T23:41:14+01:00 at alfio.manager.TicketReservationManager.cleanupExpiredReservations(TicketReservationManager.java:1008) ~[classes!/:?]
2019-12-11T23:41:14+01:00 at org.springframework.jdbc.core.namedparam.NamedParameterJdbcTemplate.update(NamedParameterJdbcTemplate.java:320) ~[spring-jdbc-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at ch.digitalfondue.npjt.QueryType$2.apply(QueryType.java:109) ~[npjt-extra-1.1.5.jar!/:?]
2019-12-11T23:41:14+01:00 at ch.digitalfondue.npjt.QueryFactory$3.invoke(QueryFactory.java:229) ~[npjt-extra-1.1.5.jar!/:?]
2019-12-11T23:41:14+01:00 at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:749) ~[spring-aop-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at alfio.manager.TicketReservationManager$$FastClassBySpringCGLIB$$e08939fb.invoke(<generated>) ~[classes!/:?]
2019-12-11T23:41:14+01:00 at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:88) ~[spring-aop-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at jdk.internal.reflect.GeneratedMethodAccessor62.invoke(Unknown Source) ~[?:?]
2019-12-11T23:41:14+01:00 at alfio.config.RowLevelSecurity$RoleAndOrganizationsAspect.setRoleAndVariable(RowLevelSecurity.java:139) ~[classes!/:?]
2019-12-11T23:41:14+01:00 at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
2019-12-11T23:41:14+01:00 at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
2019-12-11T23:41:14+01:00 at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70) ~[spring-aop-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644) ~[spring-aop-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633) ~[spring-aop-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175) ~[spring-aop-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98) ~[spring-tx-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:295) ~[spring-tx-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93) ~[spring-aop-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at alfio.manager.TicketReservationManager$$EnhancerBySpringCGLIB$$4598fa5.cleanupExpiredReservations(<generated>) ~[classes!/:?]
2019-12-11T23:41:14+01:00 at jdk.internal.reflect.GeneratedMethodAccessor76.invoke(Unknown Source) ~[?:?]
2019-12-11T23:41:14+01:00 at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688) ~[spring-aop-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
2019-12-11T23:41:14+01:00 at alfio.job.Jobs.cleanupExpiredPendingReservation(Jobs.java:180) ~[classes!/:?]
2019-12-11T23:41:14+01:00 at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
2019-12-11T23:41:14+01:00 at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) [spring-context-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
2019-12-11T23:41:14+01:00 at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
2019-12-11T23:41:14+01:00 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
2019-12-11T23:41:14+01:00 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
2019-12-11T23:41:14+01:00 at java.lang.Thread.run(Thread.java:834) [?:?]
2019-12-11T23:41:14+01:00 at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
2019-12-11T23:41:14+01:00 Caused by: org.postgresql.util.PSQLException: ERROR: update or delete on table "tickets_reservation" violates foreign key constraint "ticket_tickets_reservation_id_fkey" on table "ticket"
2019-12-11T23:41:14+01:00 at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:308) ~[postgresql-42.2.5.jar!/:42.2.5]
2019-12-11T23:41:14+01:00 at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441) ~[postgresql-42.2.5.jar!/:42.2.5]
2019-12-11T23:41:14+01:00 Detail: Key is still referenced from table "ticket".
2019-12-11T23:41:14+01:00 at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2440) ~[postgresql-42.2.5.jar!/:42.2.5]
2019-12-11T23:41:14+01:00 at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2183) ~[postgresql-42.2.5.jar!/:42.2.5]
2019-12-11T23:41:14+01:00 at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365) ~[postgresql-42.2.5.jar!/:42.2.5]
2019-12-11T23:41:14+01:00 at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:120) ~[postgresql-42.2.5.jar!/:42.2.5]
2019-12-11T23:41:14+01:00 at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-3.3.1.jar!/:?]
2019-12-11T23:41:14+01:00 at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-3.3.1.jar!/:?]
2019-12-11T23:41:14+01:00 at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:143) ~[postgresql-42.2.5.jar!/:42.2.5]
2019-12-11T23:41:14+01:00 at org.springframework.jdbc.core.JdbcTemplate.lambda$update$0(JdbcTemplate.java:866) ~[spring-jdbc-5.1.7.RELEASE.jar!/:5.1.7.RELEASE]
2019-12-11T23:41:14+01:00 ... 39 more

Version: v.2.0-M2-SNAPSHOT

Desktop (please complete the following information): N/A

Smartphone (please complete the following information): N/A

Additional context Add any other context about the problem here.

icougil commented 4 years ago

I found how to solve (at least manually the issue) !

Going to the "Reservations" part I found tooo many in "In process". image

What I did basically is selecting the oldest one (the one that probably had the problem) and I cancelled the reservation.

Doing this, the process now continues and at least is able to cancel the rest of the "In process" Reservations ;-)

cbellone commented 4 years ago

Hi @cougil, thanks for the report.

I suspect that cancelling the pending reservation didn't solve the issue of why that reservation couldn't be deleted in the first place.

I imagine you've direct access to the database. If so, can you please run the following query?

select count(*) from ticket where tickets_reservation_id = '<reservation-id-here>'

this should return 0. Unless the tickets are still attached to the reservation, which would be wrong.

other questions:

Thank you very much for your help!

icougil commented 4 years ago

Hi @cbellone

Yes, finally cancelling the Reservation solved the issue and then now no Reservations are in progress.

I ran the query and the result is 1 record 😓

Regarding your other questions: no, alf.io didn't generate an invoice for that reservation.

About the audit log, here you have it (I've obfuscated personal/sensible data):

Type    Date    User    Entity type Entity id   Modifications
RESERVATION_CREATE  04.03.2019 09:43    -   RESERVATION 282e47a0-7746-402e-bb83-54f89c38614d    
UPDATE_TICKET   04.03.2019 09:44    -   TICKET  857 
[
  {
    "newValue": true,
    "propertyName": "/assigned",
    "state": "ADDED",
    "oldValue": false
  },
  {
    "newValue": "xxx@xxx.com",
    "propertyName": "/email",
    "state": "CHANGED",
    "oldValue": ""
  },
  {
    "newValue": "xxx",
    "propertyName": "/firstName",
    "state": "ADDED",
    "oldValue": null
  },
  {
    "newValue": "xxx xxx",
    "propertyName": "/fullName",
    "state": "CHANGED",
    "oldValue": ""
  },
  {
    "newValue": "xxx",
    "propertyName": "/lastName",
    "state": "ADDED",
    "oldValue": null
  },
  {
    "newValue": "LARGE",
    "propertyName": "/{tShirtSize}",
    "state": "ADDED",
    "oldValue": null
  },
  {
    "newValue": "M",
    "propertyName": "/{gender}",
    "state": "ADDED",
    "oldValue": null
  },
(...)
  {
    "newValue": "xxx xxx",
    "propertyName": "/{Last question}",
    "state": "ADDED",
    "oldValue": null
  }
]
UPDATE_TICKET   04.03.2019 09:45    -   TICKET  857 
[
  {
    "newValue": "ACQUIRED",
    "propertyName": "/status",
    "state": "CHANGED",
    "oldValue": "PENDING"
  }
]
TERMS_CONDITION_ACCEPTED    04.03.2019 09:45    -   RESERVATION 282e47a0-7746-402e-bb83-54f89c38614d    
[
  {
    "termsAndConditionsUrl": "https://xxx.com/conditions.html"
  }
]
RESERVATION_COMPLETE    04.03.2019 09:45    -   RESERVATION 282e47a0-7746-402e-bb83-54f89c38614d    
UPDATE_TICKET_CATEGORY  19.03.2019 17:33    -   TICKET  857 
UPDATE_TICKET_CATEGORY  20.03.2019 00:06    -   TICKET  857 
UPDATE_TICKET_CATEGORY  23.03.2019 18:18    -   TICKET  857 
UPDATE_TICKET_CATEGORY  24.03.2019 23:49    -   TICKET  857 
UPDATE_TICKET_CATEGORY  15.05.2019 12:16    -   TICKET  857 
UPDATE_TICKET   12.12.2019 00:27    -   TICKET  857 
[]
RESERVATION_COMPLETE    12.12.2019 00:27    -   RESERVATION 282e47a0-7746-402e-bb83-54f89c38614d

Hope it could help.

Best regards,

cbellone commented 4 years ago

Thanks @cougil ,

From what I can see, the reservation was created on 04.03.2019 09:43 and then confirmed on 04.03.2019 09:45. That was 9 months ago. Weird.

Additionally, the reservation has been completed once again on 12.12.2019 00:27, and the timing is consistent with your second comment. So I guess it was you. Anyway this would explain why the ticket is still linked to the reservation. Because the reservation was not cancelled.

I need to understand more. Can you please post the output of the following queries to check if everything is fine on the DB:

-- this query contains the total number of seats for each event defined
select id, available_seats from event;
-- this query checks if the number of seats available is consistent with the one declared. This must be true for all events
select id, available_seats = (not_allocated_tickets + pending_tickets + sold_tickets + released_tickets + checked_in_tickets + dynamic_allocation + not_sold_tickets) as seats_match from events_statistics order by 1;
-- this shows the categories defined for each event. 
select event_id, ticket_category_id from ticket_category_statistics order by 1, 2;
-- this checks what is the ticket category for the ticket linked to this reservation
select event_id, category_id from ticket where id = 857;

thanks