Inconsistent responses when PUTting media #1481

mjordan · 2020-04-06T17:37:56Z

Creating media via HTTP PUT (docs) sometimes returns a 201 and sometimes returns a 204. Does anybody know why this is? One practical implication of this is that when Drupal responds with a 201, a location header is returned:

{'Date': 'Mon, 06 Apr 2020 15:38:20 GMT', 'Server': 'Apache/2.4.29 (Ubuntu)', 'X-Powered-By': 'PHP/7.2.29-1+ubuntu18.04.1+deb.sury.org+1', 'Cache-Control': 'must-revalidate, no-cache, private', 'Location': 'http://localhost:8000/media/193', 'X-UA-Compatible': 'IE=edge', 'Content-language': 'en', 'X-Content-Type-Options': 'nosniff', 'X-Frame-Options': 'SAMEORIGIN', 'Expires': 'Sun, 19 Nov 1978 05:00:00 GMT', 'Vary': '', 'X-Generator': 'Drupal 8 (https://www.drupal.org)', 'Content-Length': '0', 'Keep-Alive': 'timeout=5, max=100', 'Connection': 'Keep-Alive', 'Content-Type': 'text/html; charset=UTF-8'}

But when a 204 is returned, there is no location:

{'Date': 'Mon, 06 Apr 2020 15:38:24 GMT', 'Server': 'Apache/2.4.29 (Ubuntu)', 'X-Powered-By': 'PHP/7.2.29-1+ubuntu18.04.1+deb.sury.org+1', 'Cache-Control': 'must-revalidate, no-cache, private', 'X-UA-Compatible': 'IE=edge', 'Content-language': 'en', 'X-Content-Type-Options': 'nosniff', 'X-Frame-Options': 'SAMEORIGIN', 'Expires': 'Sun, 19 Nov 1978 05:00:00 GMT', 'Vary': '', 'X-Generator': 'Drupal 8 (https://www.drupal.org)', 'Keep-Alive': 'timeout=5, max=100', 'Connection': 'Keep-Alive'}

In both cases, the media appears to be created.

Some poking around in source code has led me to https://github.com/Islandora/islandora/blob/8.x-1.x/src/Controller/MediaSourceController.php#L143 as the source of this behavior but I am not clear on what triggers success or non-success. In both cases, the media appear to be created.

@dannylamb can you shed some light on this? Or any other @Islandora/8-x-committers ?

The text was updated successfully, but these errors were encountered:

whikloj · 2020-04-06T17:59:36Z

When doing a PUT normally (or my experience is) 201 CREATED means the resource did not exist and has been created, whereas 204 NO CONTENT means the resource did already exist and has been updated.

mjordan · 2020-04-06T18:42:04Z

@whikloj that is my understanding too but I am seeing this when creating new media.They don't already exists.

dannylamb · 2020-04-06T18:56:11Z

Then that's a bug 😞 The behaviour @whikloj described is the expected behaviour.

The code checks to see if the entity already exists here: https://github.com/Islandora/islandora/blob/8.x-1.x/src/MediaSource/MediaSourceService.php#L255. So somehow that's getting fooled. Or its some sort of awful timing thing. What exactly are you doing to trigger it?

seth-shaw-unlv · 2020-04-06T18:59:12Z

It's possible that we are running into timing issues; where two items are trying to be created at the same time (media being uploaded and a derivative of another item).

mjordan · 2020-04-06T19:03:03Z

It's inconsistent (at least I can't reliably replicate it). I can collect a bit more info if want (that is, try to replicate it) and report back. Anything I should be looking for in particular?

mjordan · 2020-04-06T19:04:19Z

@dannylamb

What exactly are you doing to trigger it?

Running Workbench to create new nodes and associated media. I wanted to get the new media's URL, which is in the location response header. Some media didn't have a location, which is why I dug in and noticed the 201/204 pattern.

mjordan · 2020-04-06T19:07:44Z

Is it reasonable to assume that if the controller generates a 204, the media already has a URL (i.e., a /media/xxx URL?

dannylamb · 2020-04-06T19:09:11Z

@mjordan Yes, exactly. You've already got what you seek.

dannylamb · 2020-04-06T19:09:43Z

Still worried @seth-shaw-unlv may be right, though. Are you hammering it? Exactly how big of a batch are you making?

mjordan · 2020-04-06T19:09:58Z

Let me log at https://github.com/Islandora/islandora/blob/8.x-1.x/src/Controller/MediaSourceController.php#L176 and run workbench and see what's there.

mjordan · 2020-04-06T19:10:59Z

Hammering in the sense that I am creating one after the other, within parts of a second. But not hammering it the sense that I am only creating 2 nodes/media in one run, during debugging.

mjordan · 2020-04-06T19:13:51Z

@dannylamb you start your transaction at https://github.com/Islandora/islandora/blob/8.x-1.x/src/Controller/MediaSourceController.php#L163 , but do you need to explicitly close it?

dannylamb · 2020-04-06T19:15:17Z

@mjordan IIRC the transaction autocommits when the variable goes out of scope. Let me go double check that 😅

dannylamb · 2020-04-06T19:18:58Z

According to Drupal docs, yes. They commit when the variable goes out of scope. But I don't see any harm in committing the transaction earlier sooner than later if we're running into timing issues.

dannylamb · 2020-04-06T19:21:22Z

I'm referencing https://www.drupal.org/docs/8/api/database-api/transactions fwiw

mjordan · 2020-04-06T19:23:58Z

I'm not sure if it will matter, I just noticed that it wasn't being explicitly closed.

I'll do some logging to see if I can come up with any more information.

mjordan · 2020-04-06T20:47:13Z

Ok, got something, I think: I've created about 100 media and didn't get any 204s but I did get a 500, so looked in my apache error log. Found these:

sudo tail -f  /var/log/apache2/error.log
[Mon Apr 06 20:36:18.096001 2020] [php7:notice] [pid 8883] [client 127.0.0.1:45908] Uncaught PHP Exception Symfony\\Component\\HttpKernel\\Exception\\HttpException: "SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT savepoint_1 does not exist: ROLLBACK TO SAVEPOINT savepoint_1; Array\n(\n)\n" at /var/www/html/drupal/web/modules/contrib/islandora/src/Controller/MediaSourceController.php line 192
[Mon Apr 06 20:36:52.072608 2020] [php7:notice] [pid 9828] [client 127.0.0.1:46514] Uncaught PHP Exception Symfony\\Component\\HttpKernel\\Exception\\HttpException: "SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT savepoint_1 does not exist: ROLLBACK TO SAVEPOINT savepoint_1; Array\n(\n)\n" at /var/www/html/drupal/web/modules/contrib/islandora/src/Controller/MediaSourceController.php line 192
[Mon Apr 06 20:38:04.491148 2020] [php7:notice] [pid 9933] [client 127.0.0.1:47504] Uncaught PHP Exception Symfony\\Component\\HttpKernel\\Exception\\HttpException: "SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT savepoint_1 does not exist: ROLLBACK TO SAVEPOINT savepoint_1; Array\n(\n)\n" at /var/www/html/drupal/web/modules/contrib/islandora/src/Controller/MediaSourceController.php line 192
[Mon Apr 06 20:38:22.265251 2020] [php7:notice] [pid 10494] [client 127.0.0.1:47988] Uncaught PHP Exception Symfony\\Component\\HttpKernel\\Exception\\HttpException: "SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT savepoint_1 does not exist: ROLLBACK TO SAVEPOINT savepoint_1; Array\n(\n)\n" at /var/www/html/drupal/web/modules/contrib/islandora/src/Controller/MediaSourceController.php line 192
[Mon Apr 06 20:38:54.089959 2020] [php7:notice] [pid 9758] [client 127.0.0.1:48798] Uncaught PHP Exception Symfony\\Component\\HttpKernel\\Exception\\HttpException: "SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT savepoint_1 does not exist: ROLLBACK TO SAVEPOINT savepoint_1; Array\n(\n)\n" at /var/www/html/drupal/web/modules/contrib/islandora/src/Controller/MediaSourceController.php line 192
[Mon Apr 06 20:39:19.224328 2020] [php7:notice] [pid 6980] [client 127.0.0.1:49276] Uncaught PHP Exception Symfony\\Component\\HttpKernel\\Exception\\HttpException: "SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT savepoint_1 does not exist: ROLLBACK TO SAVEPOINT savepoint_1; Array\n(\n)\n" at /var/www/html/drupal/web/modules/contrib/islandora/src/Controller/MediaSourceController.php line 192
[Mon Apr 06 20:39:22.099831 2020] [php7:notice] [pid 9758] [client 127.0.0.1:49398] Uncaught PHP Exception Symfony\\Component\\HttpKernel\\Exception\\HttpException: "SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT savepoint_1 does not exist: ROLLBACK TO SAVEPOINT savepoint_1; Array\n(\n)\n" at /var/www/html/drupal/web/modules/contrib/islandora/src/Controller/MediaSourceController.php line 192
[Mon Apr 06 20:40:28.160379 2020] [php7:notice] [pid 9933] [client 10.0.2.2:49474] Uncaught PHP Exception Symfony\\Component\\HttpKernel\\Exception\\HttpException: "SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT savepoint_1 does not exist: ROLLBACK TO SAVEPOINT savepoint_1; Array\n(\n)\n" at /var/www/html/drupal/web/modules/contrib/islandora/src/Controller/MediaSourceController.php line 192
[Mon Apr 06 20:40:45.711832 2020] [php7:notice] [pid 9758] [client 127.0.0.1:51126] Uncaught PHP Exception Symfony\\Component\\HttpKernel\\Exception\\HttpException: "SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT savepoint_1 does not exist: ROLLBACK TO SAVEPOINT savepoint_1; Array\n(\n)\n" at /var/www/html/drupal/web/modules/contrib/islandora/src/Controller/MediaSourceController.php line 192
[Mon Apr 06 20:41:13.480497 2020] [php7:notice] [pid 11151] [client 10.0.2.2:49554] Uncaught PHP Exception Symfony\\Component\\HttpKernel\\Exception\\HttpException: "SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT savepoint_1 does not exist: ROLLBACK TO SAVEPOINT savepoint_1; Array\n(\n)\n" at /var/www/html/drupal/web/modules/contrib/islandora/src/Controller/MediaSourceController.php line 192
[Mon Apr 06 20:41:49.633085 2020] [php7:notice] [pid 11136] [client 127.0.0.1:52186] Uncaught PHP Exception Symfony\\Component\\HttpKernel\\Exception\\HttpException: "SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT savepoint_1 does not exist: ROLLBACK TO SAVEPOINT savepoint_1; Array\n(\n)\n" at /var/www/html/drupal/web/modules/contrib/islandora/src/Controller/MediaSourceController.php line 192
[Mon Apr 06 20:41:57.430145 2020] [php7:notice] [pid 10047] [client 127.0.0.1:52274] Uncaught PHP Exception Symfony\\Component\\HttpKernel\\Exception\\HttpException: "'field_config' entity with ID 'media.fits_technical_metadata.fits_exiftool_exposure_time' already exists." at /var/www/html/drupal/web/modules/contrib/islandora/src/Controller/MediaSourceController.php line 192

Strange thing is, they don't correspond to 500s I was seeing as a result of my REST PUT calls, but they are all being thrown at MediaSourceController.php line 192.

dannylamb · 2020-04-07T11:06:18Z

For sure it's FITS. I get a bunch of those every time I debug it. If things aren't just so in the media_presave hook, you get these scary transaction errors.

mjordan · 2020-10-06T04:11:18Z

Still getting these errors frequently (maybe 20% of the time using a sample of 5 media doing some dev on Workbench) when PUTing media:

[Tue Oct 06 04:06:17.215598 2020] [php7:notice] [pid 4269] [client 10.0.2.2:44470] Uncaught PHP Exception Symfony\\Component\\HttpKernel\\Exception\\HttpException: "SQLSTATE[42000]: Syntax error or access violation: 1305 SAVEPOINT savepoint_1 does not exist: ROLLBACK TO SAVEPOINT savepoint_1; Array\n(\n)\n" at /var/www/html/drupal/web/modules/contrib/islandora/src/Controller/MediaSourceController.php line 192

Would love to make REST more reilable.... anything we can do? I'm using a current Vagrant.

mjordan · 2020-10-07T17:57:10Z

As discussed in the 2020-10-07 tech call, I will comment out the transaction code to see if this particular error disappears. At least that will localize the problem and we can go from there.

wgilling · 2020-10-07T18:18:17Z

During the I8 call, I didn't want to take us on another tangent but if each POST is getting processed by an individual apache client thread, and a rollback can take a longer time (depending on what all had changed), but it got me wondering if the rollback names all being the same between these processes is a potential issue. Perhaps I do not entirely know what overhead it can be to use transactions in the first place (does it lock any records, does the system handle duplicate rollback names in parallel without confusing them, etc). While this would be a separate issue (and not likely behind the reason for an initial POST to fail), it seems to me that each thread would need its own database transaction (distinct name) for what changes happened during its processing until the commit can discard the transaction information.

Initially my thought was that the first process that had to perform the rollback must have proceeded and causing the subsequent failed processes to NOT be able to rollback to their "savepoint_1" because the previous process disposed of it.

mjordan · 2020-10-19T05:44:22Z

@wgilling I don't know enough about how Drupal handles transactions to comment on your ideas. But here is the results of some testing I did:

Created 100 objects (node + PNG image) with Islandora Workbench and got 8 failed transactions.
I commented out the transaction code in the Islandora module's MediaSourceController and created two more batches of 100 objects (total 200 objects without the transaction code).
All my media were created successfully.

mjordan · 2020-12-02T00:39:18Z

@dannylamb up in #1481 (comment) you mentioned that "I don't see any harm in committing the transaction earlier sooner than later if we're running into timing issues." I'd be happy to test this. Would be good to track down this issue once and for all. Any suggestions?

mjordan · 2020-12-09T19:36:45Z

Decision at 2020-12-09 Tech call was that it's easier to change Workbench to use Drupal's file and media REST resources than to monkey with Islandora's MediaSourceController, which would be unnecessarily disruptive and non-trivial. Workbench issue is linked ^^. Thanks for the disuccsion everyone.

@dannylamb I can close this if you want.

elizoller · 2021-04-20T19:43:32Z

i'm hitting this in our production environment without any use of the workbench module.

mjordan · 2021-04-21T16:38:52Z

@elizoller during a Migration?

elizoller · 2021-04-21T18:47:39Z

yes

aOelschlager · 2023-05-25T20:10:27Z

I am getting these errors with my migrations. I'm using isle-dc and workbench. It's triggered by both fits derivatives and thumbnail derivatives. I will be running more migrations next week and I will test if the suggestion in this issue fixes the problem.

rebeccapower · 2023-05-31T18:08:21Z

Was discussed in the Open Tech Call–a complex issue that could possibly be bumped up to a working group. Possible first steps to tackling: come up with a test that reproduces the issue.
These links were provided during the discussion:
https://www.drupal.org/project/drupal/issues/1803886
https://dev.mysql.com/doc/refman/5.7/en/innodb-transaction-isolation-levels.html

rosiel · 2023-06-15T14:48:32Z

TAG met and decided to dedicate some of August's Open Meeting to a session where we figure out a way to fix this.

whikloj · 2023-06-15T20:26:46Z

Reading through the discussion at https://www.drupal.org/project/drupal/issues/1803886
and I would say this issue is very relevant and validates the discussion in Islandora-Devops/islandora-playbook#250 and anyone using MySQL should probably be making the same change. This may or may not resolve the response issue, but it might help actually diagnose the issue.

I'd also note this comment related to the savepoint_1 issue and their suggestion that this might be a red herring disguising the real issue.

rosiel · 2023-06-30T15:00:41Z

from @ruebot on the ICC call:

That error goes away if you set 'SET GLOBAL TRANSACTION ISOLATION LEVEL READ COMMITTED' on the database.

mjordan added the question label Apr 6, 2020

mjordan mentioned this issue Dec 9, 2020

Make Workbench use Drupal's built in REST interfaces for files and media mjordan/islandora_workbench#171

Closed

kstapelfeldt added the Type: question asks for support (asks a question) label Sep 25, 2021

kstapelfeldt removed the question label Sep 25, 2021

kstapelfeldt moved this to Todo in Islandora Issues Queue Feb 8, 2022

kstapelfeldt added this to Islandora Issues Queue Feb 8, 2022

aOelschlager mentioned this issue Nov 30, 2023

Issue 309 - Adding transaction isolation and default to read committed Islandora-Devops/isle-buildkit#311

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Inconsistent responses when PUTting media #1481

Inconsistent responses when PUTting media #1481

mjordan commented Apr 6, 2020 •

edited

Loading

whikloj commented Apr 6, 2020

mjordan commented Apr 6, 2020 •

edited

Loading

dannylamb commented Apr 6, 2020

seth-shaw-unlv commented Apr 6, 2020

mjordan commented Apr 6, 2020

mjordan commented Apr 6, 2020 •

edited

Loading

mjordan commented Apr 6, 2020

dannylamb commented Apr 6, 2020

dannylamb commented Apr 6, 2020

mjordan commented Apr 6, 2020

mjordan commented Apr 6, 2020

mjordan commented Apr 6, 2020

dannylamb commented Apr 6, 2020

dannylamb commented Apr 6, 2020

dannylamb commented Apr 6, 2020

mjordan commented Apr 6, 2020

mjordan commented Apr 6, 2020 •

edited

Loading

dannylamb commented Apr 7, 2020

mjordan commented Oct 6, 2020 •

edited

Loading

mjordan commented Oct 7, 2020

wgilling commented Oct 7, 2020

mjordan commented Oct 19, 2020 •

edited

Loading

mjordan commented Dec 2, 2020

mjordan commented Dec 9, 2020 •

edited

Loading

elizoller commented Apr 20, 2021

mjordan commented Apr 21, 2021

elizoller commented Apr 21, 2021

aOelschlager commented May 25, 2023

rebeccapower commented May 31, 2023

rosiel commented Jun 15, 2023

whikloj commented Jun 15, 2023

rosiel commented Jun 30, 2023

Inconsistent responses when PUTting media #1481

Inconsistent responses when PUTting media #1481

Comments

mjordan commented Apr 6, 2020 • edited Loading

whikloj commented Apr 6, 2020

mjordan commented Apr 6, 2020 • edited Loading

dannylamb commented Apr 6, 2020

seth-shaw-unlv commented Apr 6, 2020

mjordan commented Apr 6, 2020

mjordan commented Apr 6, 2020 • edited Loading

mjordan commented Apr 6, 2020

dannylamb commented Apr 6, 2020

dannylamb commented Apr 6, 2020

mjordan commented Apr 6, 2020

mjordan commented Apr 6, 2020

mjordan commented Apr 6, 2020

dannylamb commented Apr 6, 2020

dannylamb commented Apr 6, 2020

dannylamb commented Apr 6, 2020

mjordan commented Apr 6, 2020

mjordan commented Apr 6, 2020 • edited Loading

dannylamb commented Apr 7, 2020

mjordan commented Oct 6, 2020 • edited Loading

mjordan commented Oct 7, 2020

wgilling commented Oct 7, 2020

mjordan commented Oct 19, 2020 • edited Loading

mjordan commented Dec 2, 2020

mjordan commented Dec 9, 2020 • edited Loading

elizoller commented Apr 20, 2021

mjordan commented Apr 21, 2021

elizoller commented Apr 21, 2021

aOelschlager commented May 25, 2023

rebeccapower commented May 31, 2023

rosiel commented Jun 15, 2023

whikloj commented Jun 15, 2023

rosiel commented Jun 30, 2023

mjordan commented Apr 6, 2020 •

edited

Loading

mjordan commented Apr 6, 2020 •

edited

Loading

mjordan commented Apr 6, 2020 •

edited

Loading

mjordan commented Apr 6, 2020 •

edited

Loading

mjordan commented Oct 6, 2020 •

edited

Loading

mjordan commented Oct 19, 2020 •

edited

Loading

mjordan commented Dec 9, 2020 •

edited

Loading