Failure to cancel started bookings

[timdrysdale]

Once we got some load on the system this morning at 10am - coincidentally or not - started bookings could not be cancelled, according to the booking logs below.

Browser got this message in console:

{"code":"500","message":"cancelling a started booking failed because  error cancelling access at relay relay deny request failed becauseresponse status code does not match any response statuses defined for this endpoint in the swagger spec (status 404): {}"}

In the logs for book, it still looks like it might have cancelled ok, because the only difference to previous logs was a complaint that the status code was not known. What was the status code though?

$ cat /var/log/book/book.log |  grep cancel
<snip>
time="2023-02-24T00:14:08Z" level=info msg="booking cancelled" booking=engdes1-2023-Feb-27-Mon-1400-1559-pend-then-spin-024-CWYdQu-01 user=engdes1-2023-Feb-27-Mon-1400-1559-pend-then-spin-024-CWYdQu
time="2023-02-24T00:14:08Z" level=info msg="booking cancelled" booking=engdes1-2023-Feb-28-Tue-1400-1559-pend-then-spin-019-wOJ3NJ-00 user=engdes1-2023-Feb-28-Tue-1400-1559-pend-then-spin-019-wOJ3NJ
time="2023-02-24T00:14:08Z" level=info msg="booking cancelled" booking=engdes1-2023-Feb-27-Mon-1600-1759-pend-then-spin-008-k5xjoE-00 user=engdes1-2023-Feb-27-Mon-1600-1759-pend-then-spin-008-k5xjoE
time="2023-02-24T00:14:08Z" level=info msg="booking cancelled" booking=engdes1-2023-Feb-27-Mon-1400-1559-pend-then-spin-007-NRwIYP-00 user=engdes1-2023-Feb-27-Mon-1400-1559-pend-then-spin-007-NRwIYP
time="2023-02-24T00:14:08Z" level=info msg="booking cancelled" booking=engdes1-2023-Feb-27-Mon-1400-1559-spin-then-pend-007-NZ8O0M-00 user=engdes1-2023-Feb-27-Mon-1400-1559-spin-then-pend-007-NZ8O0M
time="2023-02-24T00:14:08Z" level=info msg="booking cancelled" booking=engdes1-2023-Feb-27-Mon-1600-1759-spin-then-pend-008-mFxlpe-00 user=engdes1-2023-Feb-27-Mon-1600-1759-spin-then-pend-008-mFxlpe
time="2023-02-24T00:14:08Z" level=info msg="booking cancelled" booking=engdes1-2023-Feb-27-Mon-1600-1759-pend-then-spin-017-BUGN8f-00 user=engdes1-2023-Feb-27-Mon-1600-1759-pend-then-spin-017-BUGN8f
time="2023-02-24T00:14:08Z" level=info msg="booking cancelled" booking=engdes1-2023-Feb-28-Tue-1600-1759-pend-then-spin-009-eCmK3S-00 user=engdes1-2023-Feb-28-Tue-1600-1759-pend-then-spin-009-eCmK3S
time="2023-02-24T08:24:03Z" level=info msg="deny successful at cancelling session at relay" request="{0xc00091cd80 https://dev.practable.io/access 82bb9b5b-a7e4-4511-b53e-a0b4c8027f58 1677227280}"
time="2023-02-24T08:24:03Z" level=info msg="access cancelled at relay" booking=82bb9b5b-a7e4-4511-b53e-a0b4c8027f58 user=cfs62heot5urgb4g7ff0
time="2023-02-24T08:24:03Z" level=info msg="booking cancelled" booking=82bb9b5b-a7e4-4511-b53e-a0b4c8027f58 user=cfs62heot5urgb4g7ff0
time="2023-02-24T08:24:03Z" level=info msg="booking cancelled successfully" booking=82bb9b5b-a7e4-4511-b53e-a0b4c8027f58 user=cfs62heot5urgb4g7ff0
time="2023-02-24T09:48:20Z" level=info msg="deny successful at cancelling session at relay" request="{0xc00091ca20 https://dev.practable.io/access fec98624-471e-47b6-abb8-345f3e04fc8b 1677232200}"
time="2023-02-24T09:48:20Z" level=info msg="access cancelled at relay" booking=fec98624-471e-47b6-abb8-345f3e04fc8b user=cfrq6iuot5urgb4g7fdg
time="2023-02-24T09:48:20Z" level=error msg="cancelling a started booking failed because  error cancelling access at relay relay deny request failed becauseresponse status code does not match any response statuses defined for this endpoint in the swagger spec (status 404): {}" booking=fec98624-471e-47b6-abb8-345f3e04fc8b user=cfrq6iuot5urgb4g7fdg
time="2023-02-24T09:54:13Z" level=info msg="deny successful at cancelling session at relay" request="{0xc00010e8a0 https://dev.practable.io/access 29340c8f-db39-42e8-820d-6a3531785848 1677232560}"
time="2023-02-24T09:54:13Z" level=info msg="access cancelled at relay" booking=29340c8f-db39-42e8-820d-6a3531785848 user=cfrq6iuot5urgb4g7fdg
time="2023-02-24T09:54:13Z" level=error msg="cancelling a started booking failed because  error cancelling access at relay relay deny request failed becauseresponse status code does not match any response statuses defined for this endpoint in the swagger spec (status 404): {}" booking=29340c8f-db39-42e8-820d-6a3531785848 user=cfrq6iuot5urgb4g7fdg
time="2023-02-24T09:54:16Z" level=info msg="deny successful at cancelling session at relay" request="{0xc0005d5f80 https://dev.practable.io/access 29340c8f-db39-42e8-820d-6a3531785848 1677232560}"
time="2023-02-24T09:54:16Z" level=info msg="access cancelled at relay" booking=29340c8f-db39-42e8-820d-6a3531785848 user=cfrq6iuot5urgb4g7fdg
time="2023-02-24T09:54:16Z" level=error msg="cancelling a started booking failed because  error cancelling access at relay relay deny request failed becauseresponse status code does not match any response statuses defined for this endpoint in the swagger spec (status 404): {}" booking=29340c8f-db39-42e8-820d-6a3531785848 user=cfrq6iuot5urgb4g7fdg
time="2023-02-24T09:56:37Z" level=error msg="cancelling a started booking failed because  error cancelling access at relay relay deny request failed becauseresponse status code does not match any response statuses defined for this endpoint in the swagger spec (status 404): {}" booking=7a3cf5d6-0de0-46b6-a391-1aab638a8644 user=cfrq6iuot5urgb4g7fdg
time="2023-02-24T09:56:41Z" level=info msg="deny successful at cancelling session at relay" request="{0xc0005d5ce0 https://dev.practable.io/access 7a3cf5d6-0de0-46b6-a391-1aab638a8644 1677232740}"
time="2023-02-24T09:56:41Z" level=info msg="access cancelled at relay" booking=7a3cf5d6-0de0-46b6-a391-1aab638a8644 user=cfrq6iuot5urgb4g7fdg
time="2023-02-24T09:56:41Z" level=error msg="cancelling a started booking failed because  error cancelling access at relay relay deny request failed becauseresponse status code does not match any response statuses defined for this endpoint in the swagger spec (status 404): {}" booking=7a3cf5d6-0de0-46b6-a391-1aab638a8644 user=cfrq6iuot5urgb4g7fdg
time="2023-02-24T10:21:01Z" level=info msg="deny successful at cancelling session at relay" request="{0xc00010f8c0 https://dev.practable.io/access c8a005e5-18c8-45cc-9fc3-98e374c6eb17 1677237300}"
time="2023-02-24T10:21:01Z" level=info msg="access cancelled at relay" booking=c8a005e5-18c8-45cc-9fc3-98e374c6eb17 user=cfrub8uot5urgb4g7fe0
time="2023-02-24T10:21:01Z" level=error msg="cancelling a started booking failed because  error cancelling access at relay relay deny request failed becauseresponse status code does not match any response statuses defined for this endpoint in the swagger spec (status 404): {}" booking=c8a005e5-18c8-45cc-9fc3-98e374c6eb17 user=cfrub8uot5urgb4g7fe0
time="2023-02-24T10:28:58Z" level=info msg="deny successful at cancelling session at relay" request="{0xc00091d8c0 https://dev.practable.io/access c8a005e5-18c8-45cc-9fc3-98e374c6eb17 1677237300}"
time="2023-02-24T10:28:58Z" level=info msg="access cancelled at relay" booking=c8a005e5-18c8-45cc-9fc3-98e374c6eb17 user=cfrub8uot5urgb4g7fe0
time="2023-02-24T10:28:58Z" level=error msg="cancelling a started booking failed because  error cancelling access at relay relay deny request failed becauseresponse status code does not match any response statuses defined for this endpoint in the swagger spec (status 404): {}" booking=c8a005e5-18c8-45cc-9fc3-98e374c6eb17 user=cfrub8uot5urgb4g7fe0
tim@instance-1:~$ 

Earlier, the log messages for successful cancel after starts looked like this:

ime="2023-02-21T15:14:48Z" level=info msg="deny successful at cancelling session at relay" request="{0xc00010e5a0 https://dev.practable.io/access 76151c8c-c6c0-42a3-951b-226f9c8a014a 1676993340}"
time="2023-02-21T15:14:48Z" level=info msg="access cancelled at relay" booking=76151c8c-c6c0-42a3-951b-226f9c8a014a user=cfqdssuot5urgb4g7fa0
time="2023-02-21T15:14:48Z" level=info msg="booking cancelled" booking=76151c8c-c6c0-42a3-951b-226f9c8a014a user=cfqdssuot5urgb4g7fa0
time="2023-02-21T15:14:48Z" level=info msg="booking cancelled successfully" booking=76151c8c-c6c0-42a3-951b-226f9c8a014a user=cfqdssuot5urgb4g7fa0
time="2023-02-22T10:10:06Z" level=info msg="deny successful at cancelling session at relay" request="{0xc0005d5c20 https://dev.practable.io/access ef05d7fb-3997-4b1e-b77b-309b9adbeb6b 1677061380}"
time="2023-02-22T10:10:06Z" level=info msg="access cancelled at relay" booking=ef05d7fb-3997-4b1e-b77b-309b9adbeb6b user=cfq98huot5urgb4g7f80
time="2023-02-22T10:10:06Z" level=info msg="booking cancelled" booking=ef05d7fb-3997-4b1e-b77b-309b9adbeb6b user=cfq98huot5urgb4g7f80
time="2023-02-22T10:10:06Z" level=info msg="booking cancelled successfully" booking=ef05d7fb-3997-4b1e-b77b-309b9adbeb6b user=cfq98huot5urgb4g7f80
time="2023-02-22T10:10:08Z" level=info msg="deny successful at cancelling session at relay" request="{0xc00091c7e0 https://dev.practable.io/access 1f07f16d-e99a-4c5a-af36-66a7d8d6884e 1677061440}"
time="2023-02-22T10:10:08Z" level=info msg="access cancelled at relay" booking=1f07f16d-e99a-4c5a-af36-66a7d8d6884e user=cfq98huot5urgb4g7f80
time="2023-02-22T10:10:08Z" level=info msg="booking cancelled" booking=1f07f16d-e99a-4c5a-af36-66a7d8d6884e user=cfq98huot5urgb4g7f80
time="2023-02-22T10:10:08Z" level=info msg="booking cancelled successfully" booking=1f07f16d-e99a-4c5a-af36-66a7d8d6884e user=cfq98huot5urgb4g7f80
time="2023-02-22T19:13:20Z" level=info msg="deny successful at cancelling session at relay" request="{0xc00091c720 https://dev.practable.io/access cc249c78-9726-4b75-9411-38257e6e59fb 1677093480}"
time="2023-02-22T19:13:20Z" level=info msg="access cancelled at relay" booking=cc249c78-9726-4b75-9411-38257e6e59fb user=cfpu16uot5urgb4g7f7g
time="2023-02-22T19:13:20Z" level=info msg="booking cancelled" booking=cc249c78-9726-4b75-9411-38257e6e59fb user=cfpu16uot5urgb4g7f7g
time="2023-02-22T19:13:20Z" level=info msg="booking cancelled successfully" booking=cc249c78-9726-4b75-9411-38257e6e59fb user=cfpu16uot5urgb4g7f7g
time="2023-02-23T16:56:51Z" level=info msg="deny successful at cancelling session at relay" request="{0xc000ab6ea0 https://dev.practable.io/access 57718e85-3012-461c-95be-1fa27610afe8 1677172200}"
time="2023-02-23T16:56:51Z" level=info msg="access cancelled at relay" booking=57718e85-3012-461c-95be-1fa27610afe8 user=cfrmi6eot5urgb4g7fcg
time="2023-02-23T16:56:51Z" level=info msg="booking cancelled" booking=57718e85-3012-461c-95be-1fa27610afe8 user=cfrmi6eot5urgb4g7fcg
time="2023-02-23T16:56:51Z" level=info msg="booking cancelled successfully" booking=57718e85-3012-461c-95be-1fa27610afe8 user=cfrmi6eot5urgb4g7fcg
time="2023-02-23T16:56:54Z" level=info msg="deny successful at cancelling session at relay" request="{0xc00010e780 https://dev.practable.io/access d9b0d685-c65f-46bb-b96d-e0a5218463ba 1677172200}"
time="2023-02-23T16:56:54Z" level=info msg="access cancelled at relay" booking=d9b0d685-c65f-46bb-b96d-e0a5218463ba user=cfrmi6eot5urgb4g7fcg
time="2023-02-23T16:56:54Z" level=info msg="booking cancelled" booking=d9b0d685-c65f-46bb-b96d-e0a5218463ba user=cfrmi6eot5urgb4g7fcg
time="2023-02-23T16:56:54Z" level=info msg="booking cancelled successfully" booking=d9b0d685-c65f-46bb-b96d-e0a5218463ba user=cfrmi6eot5urgb4g7fcg
time="2023-02-23T17:33:43Z" level=info msg="deny successful at cancelling session at relay" request="{0xc00010ede0 https://dev.practable.io/access 5fb18ae5-62ce-4dbe-9d9a-aa030cd945b7 1677174480}"
time="2023-02-23T17:33:43Z" level=info msg="access cancelled at relay" booking=5fb18ae5-62ce-4dbe-9d9a-aa030cd945b7 user=cfrq6iuot5urgb4g7fdg
time="2023-02-23T17:33:43Z" level=info msg="booking cancelled" booking=5fb18ae5-62ce-4dbe-9d9a-aa030cd945b7 user=cfrq6iuot5urgb4g7fdg
time="2023-02-23T17:33:43Z" level=info msg="booking cancelled successfully" booking=5fb18ae5-62ce-4dbe-9d9a-aa030cd945b7 user=cfrq6iuot5urgb4g7fdg
time="2023-02-23T20:15:18Z" level=info msg="deny successful at cancelling session at relay" request="{0xc00010e5a0 https://dev.practable.io/access 1cfe280f-7837-4ae6-899a-ca382d51b9a0 1677184140}"
time="2023-02-23T20:15:18Z" level=info msg="access cancelled at relay" booking=1cfe280f-7837-4ae6-899a-ca382d51b9a0 user=cfrmi6eot5urgb4g7fcg
time="2023-02-23T20:15:18Z" level=info msg="booking cancelled" booking=1cfe280f-7837-4ae6-899a-ca382d51b9a0 user=cfrmi6eot5urgb4g7fcg
time="2023-02-23T20:15:18Z" level=info msg="booking cancelled successfully" booking=1cfe280f-7837-4ae6-899a-ca382d51b9a0 user=cfrmi6eot5urgb4g7fcg

[timdrysdale]

Response code from relay has been 204 everytime - see below. This suggests that the issue lies in how book is handling the response from the relay.

First there are the cancellation requests received by book (some 204, mostly 500 though)
Then there are the access/bids/deny received by relay from book (all 204)

$ cat /var/log/nginx/access.log | grep DELETE
148.252.128.127 - - [24/Feb/2023:08:24:03 +0000] "DELETE /book/api/v1/users/cfs62heot5urgb4g7ff0/bookings/82bb9b5b-a7e4-4511-b53e-a0b4c8027f58 HTTP/1.1" 404 37 "https://dev.practable.io/book/cancelConfirm/82bb9b5b-a7e4-4511-b53e-a0b4c8027f58" "Mozilla/5.0 (Android 13; Mobile; rv:109.0) Gecko/110.0 Firefox/110.0"
192.41.114.228 - - [24/Feb/2023:09:48:20 +0000] "DELETE /book/api/v1/users/cfrq6iuot5urgb4g7fdg/bookings/fec98624-471e-47b6-abb8-345f3e04fc8b HTTP/1.1" 500 259 "https://dev.practable.io/book/cancelConfirm/fec98624-471e-47b6-abb8-345f3e04fc8b" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/109.0"
192.41.114.228 - - [24/Feb/2023:09:50:12 +0000] "DELETE /book/api/v1/users/cfrq6iuot5urgb4g7fdg/bookings/fec98624-471e-47b6-abb8-345f3e04fc8b HTTP/1.1" 500 72 "https://dev.practable.io/book/cancelConfirm/fec98624-471e-47b6-abb8-345f3e04fc8b" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/109.0"
192.41.114.228 - - [24/Feb/2023:09:54:13 +0000] "DELETE /book/api/v1/users/cfrq6iuot5urgb4g7fdg/bookings/29340c8f-db39-42e8-820d-6a3531785848 HTTP/1.1" 500 259 "https://dev.practable.io/book/cancelConfirm/29340c8f-db39-42e8-820d-6a3531785848" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/109.0"
192.41.114.228 - - [24/Feb/2023:09:54:16 +0000] "DELETE /book/api/v1/users/cfrq6iuot5urgb4g7fdg/bookings/29340c8f-db39-42e8-820d-6a3531785848 HTTP/1.1" 500 259 "https://dev.practable.io/book/cancelConfirm/29340c8f-db39-42e8-820d-6a3531785848" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/109.0"
192.41.114.228 - - [24/Feb/2023:09:56:34 +0000] "DELETE /book/api/v1/users/cfrq6iuot5urgb4g7fdg/bookings/29340c8f-db39-42e8-820d-6a3531785848 HTTP/1.1" 500 72 "https://dev.practable.io/book/cancelConfirm/29340c8f-db39-42e8-820d-6a3531785848" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/109.0"
192.41.114.228 - - [24/Feb/2023:09:56:37 +0000] "DELETE /book/api/v1/users/cfrq6iuot5urgb4g7fdg/bookings/7a3cf5d6-0de0-46b6-a391-1aab638a8644 HTTP/1.1" 500 259 "https://dev.practable.io/book/cancelConfirm/7a3cf5d6-0de0-46b6-a391-1aab638a8644" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/109.0"
192.41.114.228 - - [24/Feb/2023:09:56:41 +0000] "DELETE /book/api/v1/users/cfrq6iuot5urgb4g7fdg/bookings/7a3cf5d6-0de0-46b6-a391-1aab638a8644 HTTP/1.1" 500 259 "https://dev.practable.io/book/cancelConfirm/7a3cf5d6-0de0-46b6-a391-1aab638a8644" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/109.0"
92.239.205.252 - - [24/Feb/2023:10:21:01 +0000] "DELETE /book/api/v1/users/cfrub8uot5urgb4g7fe0/bookings/c8a005e5-18c8-45cc-9fc3-98e374c6eb17 HTTP/1.1" 500 259 "https://dev.practable.io/book/cancelConfirm/c8a005e5-18c8-45cc-9fc3-98e374c6eb17?group=g-engdes1-lab" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36"
92.239.205.252 - - [24/Feb/2023:10:28:58 +0000] "DELETE /book/api/v1/users/cfrub8uot5urgb4g7fe0/bookings/c8a005e5-18c8-45cc-9fc3-98e374c6eb17 HTTP/1.1" 500 259 "https://dev.practable.io/book/cancelConfirm/c8a005e5-18c8-45cc-9fc3-98e374c6eb17?group=g-engdes1-lab" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36"
92.239.205.252 - - [24/Feb/2023:10:37:53 +0000] "DELETE /book/api/v1/users/cfrub8uot5urgb4g7fe0/bookings/eb141e15-a309-4b87-aa73-fb07bd8f83fa HTTP/1.1" 500 259 "https://dev.practable.io/book/cancelConfirm/eb141e15-a309-4b87-aa73-fb07bd8f83fa?group=g-engdes1-lab" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36"
92.239.205.252 - - [24/Feb/2023:10:37:59 +0000] "DELETE /book/api/v1/users/cfrub8uot5urgb4g7fe0/bookings/ddfc4819-4721-4128-a6b6-b56332ccddd1 HTTP/1.1" 404 37 "https://dev.practable.io/book/cancelConfirm/ddfc4819-4721-4128-a6b6-b56332ccddd1?group=g-engdes1-lab" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36"
92.239.205.252 - - [24/Feb/2023:10:38:04 +0000] "DELETE /book/api/v1/users/cfrub8uot5urgb4g7fe0/bookings/eb141e15-a309-4b87-aa73-fb07bd8f83fa HTTP/1.1" 500 259 "https://dev.practable.io/book/cancelConfirm/eb141e15-a309-4b87-aa73-fb07bd8f83fa?group=g-engdes1-lab" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36"
92.239.205.252 - - [24/Feb/2023:10:38:10 +0000] "DELETE /book/api/v1/users/cfrub8uot5urgb4g7fe0/bookings/eb141e15-a309-4b87-aa73-fb07bd8f83fa HTTP/1.1" 500 259 "https://dev.practable.io/book/cancelConfirm/eb141e15-a309-4b87-aa73-fb07bd8f83fa?group=g-engdes1-lab" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36"

$ cat /var/log/nginx/access.log | grep "bid"
34.105.220.20 - - [24/Feb/2023:08:24:03 +0000] "POST /access/bids/deny?bid=82bb9b5b-a7e4-4511-b53e-a0b4c8027f58&exp=1677227280 HTTP/1.1" 204 0 "-" "Go-http-client/1.1"
34.105.220.20 - - [24/Feb/2023:09:48:20 +0000] "POST /access/bids/deny?bid=fec98624-471e-47b6-abb8-345f3e04fc8b&exp=1677232200 HTTP/1.1" 204 0 "-" "Go-http-client/1.1"
34.105.220.20 - - [24/Feb/2023:09:54:13 +0000] "POST /access/bids/deny?bid=29340c8f-db39-42e8-820d-6a3531785848&exp=1677232560 HTTP/1.1" 204 0 "-" "Go-http-client/1.1"
34.105.220.20 - - [24/Feb/2023:09:54:16 +0000] "POST /access/bids/deny?bid=29340c8f-db39-42e8-820d-6a3531785848&exp=1677232560 HTTP/1.1" 204 0 "-" "Go-http-client/1.1"
34.105.220.20 - - [24/Feb/2023:09:56:41 +0000] "POST /access/bids/deny?bid=7a3cf5d6-0de0-46b6-a391-1aab638a8644&exp=1677232740 HTTP/1.1" 204 0 "-" "Go-http-client/1.1"
34.105.220.20 - - [24/Feb/2023:10:21:01 +0000] "POST /access/bids/deny?bid=c8a005e5-18c8-45cc-9fc3-98e374c6eb17&exp=1677237300 HTTP/1.1" 204 0 "-" "Go-http-client/1.1"
34.105.220.20 - - [24/Feb/2023:10:28:58 +0000] "POST /access/bids/deny?bid=c8a005e5-18c8-45cc-9fc3-98e374c6eb17&exp=1677237300 HTTP/1.1" 204 0 "-" "Go-http-client/1.1"
34.105.220.20 - - [24/Feb/2023:10:37:53 +0000] "POST /access/bids/deny?bid=eb141e15-a309-4b87-aa73-fb07bd8f83fa&exp=1677237600 HTTP/1.1" 204 0 "-" "Go-http-client/1.1"
34.105.220.20 - - [24/Feb/2023:10:38:04 +0000] "POST /access/bids/deny?bid=eb141e15-a309-4b87-aa73-fb07bd8f83fa&exp=1677237600 HTTP/1.1" 204 0 "-" "Go-http-client/1.1"
34.105.220.20 - - [24/Feb/2023:10:38:10 +0000] "POST /access/bids/deny?bid=eb141e15-a309-4b87-aa73-fb07bd8f83fa&exp=1677237600 HTTP/1.1" 204 0 "-" "Go-http-client/1.1"

$ cat /var/log/nginx/error.log | grep "bid"
(empty)

[timdrysdale]

So - a successful deletion at relay confirmed with observation of video and data stopping on an app instance that was open (spin30), yet same signature in the logs => issue is definitely in how book is handling the response from relay

34.105.220.20 - - [24/Feb/2023:11:07:56 +0000] "POST /access/bids/deny?bid=5d6af3ed-9780-4017-8b3f-a592815f28a4&exp=1677237000 HTTP/1.1" 204 0 "-" "Go-http-client/1.1"

92.239.205.252 - - [24/Feb/2023:11:07:56 +0000] "DELETE /book/api/v1/users/cfrub8uot5urgb4g7fe0/bookings/5d6af3ed-9780-4017-8b3f-a592815f28a4 HTTP/1.1" 500 259 "https://dev.practable.io/book/cancelConfirm/5d6af3ed-9780-4017-8b3f-a592815f28a4?group=g-engdes1-lab" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36"

[timdrysdale]

This time there was no response from book, just the 500 message with an empty response.

Looking back at the earlier console message, we need to find where the words response status code does not match any response statuses defined for this endpoint in the swagger spec come from.

store.go is not responsible:

		DONE:
			for {
				select {
				case result, ok := <-c:
					if ok && result == "ok" {
						// deny request was successful
						log.WithFields(log.Fields{"user": b.User, "booking": b.Name}).Info("access cancelled at relay")
						break DONE
					} else {
						msg = msg + " error cancelling access at relay " + result
						log.WithFields(log.Fields{"user": b.User, "booking": b.Name}).Error(msg)
						return errors.New(msg)
					}
				case <-time.After(s.requestTimeout):
					msg = msg + " timed out cancelling access at relay " + URL
					log.WithFields(log.Fields{"user": b.User, "booking": b.Name}).Error(msg)
					return errors.New(msg)
				}
			}

		}

[timdrysdale]

in deny.go we have the source of the error message (from the client)

			client := ac.NewHTTPClientWithConfig(nil, trans)
			param := ao.NewDenyParams().WithTimeout(c.Timeout).WithBid(req.BookingID).WithExp(req.ExpiresAt)
			payload, err := client.Operations.Deny(param, auth)

			if err != nil {
				msg := "relay deny request failed because" + err.Error()
				log.WithFields(log.Fields{"request": req}).Error("deny error is" + msg)
				req.Result <- msg
				break NEXT
			}

			if !payload.IsSuccess() {
				msg := "relay deny request failed because" + payload.String()
				log.WithFields(log.Fields{"request": req}).Error("deny error is" + msg)
				req.Result <- msg
				break NEXT
			}

			log.WithFields(log.Fields{"request": req}).Info("deny successful at cancelling session at relay")
			req.Result <- "ok"
		}

which produced these logs

time="2023-02-24T11:07:56Z" level=debug msg="deny request received" request="{0xc000b200c0 https://dev.practable.io/access 5d6af3ed-9780-4017-8b3f-a592815f28a4 1677237000}"
time="2023-02-24T11:07:56Z" level=info msg="deny successful at cancelling session at relay" request="{0xc000b200c0 https://dev.practable.io/access 5d6af3ed-9780-4017-8b3f-a592815f28a4 1677237000}"
time="2023-02-24T11:07:56Z" level=debug msg="deny request received" request="{0xc000b20720 https://relay-access.practable.io 5d6af3ed-9780-4017-8b3f-a592815f28a4 1677237000}"
time="2023-02-24T11:07:56Z" level=error msg="deny error isrelay deny request failed becauseresponse status code does not match any response statuses defined for this endpoint in the swagger spec (status 404): {}" request="{0xc000b20720 https://relay-access.practable.io 5d6af3ed-9780-4017-8b3f-a592815f28a4 1677237000}"
time="2023-02-24T11:07:56Z" level=error msg="cancelling a started booking failed because  error cancelling access at relay relay deny request failed becauseresponse status code does not match any response statuses defined for this endpoint in the swagger spec (status 404): {}" booking=5d6af3ed-9780-4017-8b3f-a592815f28a4 user=cfrub8uot5urgb4g7fe0

[timdrysdale]

Probably something getting out of sequence in the comms, so revisit when time to debug properly. Meanwhile,
v0.3.9 - hotfix, ignore errors in response.

[timdrysdale]

hot fix hasn't been problematic, so closing this issue