search

MauroDataMapper / mdm-core

The backend of MDM
Apache License 2.0
7 stars 3 forks source link

Getting unused profiles on a folder fails when the folder label includes "@" #260

Open pjmonks opened 2 years ago

pjmonks commented 2 years ago

Please fill in the sections below, adding/removing information where applicable:

Description

The /api/folder/{id}/profiles/unused endpoint returns a 500 if the folder label includes an "@" character. Also, the stacktrace suggests that a DB update is happening when only a fetch should happen.

Steps to reproduce

  1. Create a folder with a label that includes an "@" character e.g. named after an email address.
  2. Call GET /api/folder/{id}/profiles/unused

Expected behavior

Should return a 200 with a list of any unused available profiles.

Environment

Please complete the following information:

Additional context

The "@" character in a label should not be typically used, in fact it is probably a reserved character for pathing. However, this seems to reproduce this error consistently.

Error Details

Server Error

We're sorry, but the server responded with an error message.

Details

{
  "headers": {
    "normalizedNames": {},
    "lazyUpdate": null
  },
  "status": 500,
  "statusText": "OK",
  "url": "http://localhost:8080/api/folders/aa58aa1c-1618-4200-92a4-0349809d2e7b/profiles/unused",
  "ok": false,
  "name": "HttpErrorResponse",
  "message": "Http failure response for http://localhost:8080/api/folders/aa58aa1c-1618-4200-92a4-0349809d2e7b/profiles/unused: 500 OK",
  "error": {
    "status": 500,
    "reason": "Internal Server Error",
    "errorCode": "UEX--",
    "message": "Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: update core.folder set version=?, date_created=?, last_updated=?, path=?, deleted=?, readable_by_authenticated_users=?, parent_folder_id=?, created_by=?, readable_by_everyone=?, label=?, description=? where id=? and version=?",
    "path": "/api/folders/aa58aa1c-1618-4200-92a4-0349809d2e7b/profiles/unused",
    "environment": "DEVELOPMENT",
    "version": "5.0.0-SNAPSHOT",
    "exception": {
      "type": "StaleStateException",
      "message": "Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: update core.folder set version=?, date_created=?, last_updated=?, path=?, deleted=?, readable_by_authenticated_users=?, parent_folder_id=?, created_by=?, readable_by_everyone=?, label=?, description=? where id=? and version=?",
      "stacktrace": [
        "org.hibernate.jdbc.Expectations$BasicExpectation.checkBatched(Expectations.java:67)",
        "org.hibernate.jdbc.Expectations$BasicExpectation.verifyOutcome(Expectations.java:54)",
        "org.hibernate.engine.jdbc.batch.internal.BatchingBatch.checkRowCounts(BatchingBatch.java:151)",
        "org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:126)",
        "org.hibernate.engine.jdbc.batch.internal.BatchingBatch.doExecuteBatch(BatchingBatch.java:106)",
        "org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.execute(AbstractBatchImpl.java:148)",
        "org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.executeBatch(JdbcCoordinatorImpl.java:198)",
        "org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:633)",
        "org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478)",
        "java.util.LinkedHashMap.forEach(LinkedHashMap.java:721)",
        "org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475)",
        "org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:344)",
        "org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40)",
        "org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:107)",
        "org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1402)",
        "org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:493)",
        "org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3285)",
        "org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2420)",
        "org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:449)",
        "org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183)",
        "org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:40)",
        "org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281)",
        "org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101)",
        "org.springframework.orm.hibernate5.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:643)",
        "org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743)",
        "org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711)",
        "org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:152)",
        "grails.gorm.transactions.GrailsTransactionTemplate.execute(GrailsTransactionTemplate.groovy:91)",
        "uk.ac.ox.softeng.maurodatamapper.profile.ProfileController.unusedProfiles(ProfileController.groovy:70)",
        "jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)",
        "org.grails.core.DefaultGrailsControllerClass$ReflectionInvoker.invoke(DefaultGrailsControllerClass.java:211)",
        "org.grails.core.DefaultGrailsControllerClass.invoke(DefaultGrailsControllerClass.java:188)",
        "org.grails.web.mapping.mvc.UrlMappingsInfoHandlerAdapter.handle(UrlMappingsInfoHandlerAdapter.groovy:90)",
        "org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067)",
        "org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)",
        "org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)",
        "org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)",
        "org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)",
        "org.grails.web.servlet.mvc.GrailsWebRequestFilter.doFilterInternal(GrailsWebRequestFilter.java:77)",
        "org.grails.web.filters.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:67)",
        "java.lang.Thread.run(Thread.java:833)"
      ]
    }
  }
}
joe-crawford commented 2 years ago

FYI @olliefreeman, I have been able to replicate this in the UI by creating a folder, then creating a folder within it with the label 'test@example.com', then when trying to navigate to this folder in the UI, the StaleStateException/Batch update returned unexpected row count from update error reliably occurs on the /api/folders/{folderId}/profiles/unused endpoint.

Looking in the Chrome Network Inspector, when opening the problematic folder, the call to GET the /api/folders/{folderId}/permissions endpoint is successful and returns the correct permissions, but it takes a few hundred ms to succeed. When opening another folder, without an '@' in the label, with the same permissions within the same top level folder, the GET /api/folders/{folderId}/permissions only takes around 20ms to succeed.

I've been able to see the same error in Postman by using a script to repeatedly call the permissions endpoint on the problematic folder:

import java.time.LocalDateTime

count = 0

String url = 'http://localhost:8080/api/folders/c3100f09-f68d-47eb-93f3-4e18053a3822/permissions'

while(true) {
    HttpURLConnection connection = url.toURL().openConnection()
    connection.setRequestProperty('cookie','JSESSIONID=B821DA06E1E8F81F1BCDD97FFC351B0F')
    connection.setRequestMethod("GET");
    connection.connect()
    int code = connection.getResponseCode()

    if (code != 200 ) {
        println("${LocalDateTime.now()}: ${code} : ${connection.getErrorStream().text}")
    }
    count++
}

Then calling GET /api/folders/{folderId}/profiles/unused in Postman around 10 times, most calls succeed but sometimes the error occurs:

{
    "status": 500,
    "reason": "Internal Server Error",
    "errorCode": "UEX--",
    "message": "Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: update core.folder set version=?, date_created=?, last_updated=?, path=?, deleted=?, readable_by_authenticated_users=?, parent_folder_id=?, created_by=?, readable_by_everyone=?, label=?, description=? where id=? and version=?",
    "path": "/api/folders/9e3dd266-bd0f-48a1-be6c-89646faade5e/profiles/unused",
    "environment": "DEVELOPMENT",
    "version": "5.1.0-SNAPSHOT",
    "exception": {
        "type": "StaleStateException",
        "message": "Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: update core.folder set version=?, date_created=?, last_updated=?, path=?, deleted=?, readable_by_authenticated_users=?, parent_folder_id=?, created_by=?, readable_by_everyone=?, label=?, description=? where id=? and version=?",
        "stacktrace": [
            "org.hibernate.jdbc.Expectations$BasicExpectation.checkBatched(Expectations.java:67)",
            "org.hibernate.jdbc.Expectations$BasicExpectation.verifyOutcome(Expectations.java:54)",
            "org.hibernate.engine.jdbc.batch.internal.BatchingBatch.checkRowCounts(BatchingBatch.java:151)",
            "org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:126)",
            "org.hibernate.engine.jdbc.batch.internal.BatchingBatch.doExecuteBatch(BatchingBatch.java:106)",
            "org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.execute(AbstractBatchImpl.java:148)",
            "org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.executeBatch(JdbcCoordinatorImpl.java:198)",
            "org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:633)",
            "org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478)",
            "java.util.LinkedHashMap.forEach(LinkedHashMap.java:721)",
            "org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475)",
            "org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:344)",
            "org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40)",
            "org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:107)",
            "org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1416)",
            "org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:507)",
            "org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3299)",
            "org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2434)",
            "org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:449)",
            "org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183)",
            "org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:40)",
            "org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281)",
            "org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101)",
            "org.springframework.orm.hibernate5.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:643)",
            "org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743)",
            "org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711)",
            "org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:152)",
            "grails.gorm.transactions.GrailsTransactionTemplate.execute(GrailsTransactionTemplate.groovy:91)",
            "uk.ac.ox.softeng.maurodatamapper.profile.ProfileController.unusedProfiles(ProfileController.groovy:70)",
            "jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)",
            "org.grails.core.DefaultGrailsControllerClass$ReflectionInvoker.invoke(DefaultGrailsControllerClass.java:211)",
            "org.grails.core.DefaultGrailsControllerClass.invoke(DefaultGrailsControllerClass.java:188)",
            "org.grails.web.mapping.mvc.UrlMappingsInfoHandlerAdapter.handle(UrlMappingsInfoHandlerAdapter.groovy:90)",
            "org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067)",
            "org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)",
            "org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)",
            "org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)",
            "org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)",
            "org.grails.web.servlet.mvc.GrailsWebRequestFilter.doFilterInternal(GrailsWebRequestFilter.java:77)",
            "org.grails.web.filters.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:67)",
            "java.lang.Thread.run(Thread.java:833)"
        ]
    }
}

Both with the script and the UI, I can only replicate the issue with a nested folder with an '@' in the label, I haven't seen the error on a top-level folder even if it has '@' in the label.

olliefreeman commented 2 years ago

the first call to the permissions endpoint, no matter the id, always takes longer than subsequent calls

joe-crawford commented 2 years ago

I'm consistently seeing the permissions endpoint for the folder with the '@' label take longer (about 8x) so I think something different may be happening there.

olliefreeman commented 2 years ago

using postman

after performing either of the above, making any repeated calls to either of the permissions endpoints get 20ms as long as i dont restart the backend.

olliefreeman commented 2 years ago

cannot replicate this issue even using the below. i am firm on the belief that its got nothing to do with the permissions endpoint.... plus as the permissions endpoint makes no updates it still doesnt explain the reason for the StaleStateException

import java.time.LocalDateTime
import java.util.concurrent.Callable
import java.util.concurrent.ExecutorService
import java.util.concurrent.Executors

ExecutorService executorService = Executors.newFixedThreadPool(10)

executorService.invokeAll([
    new Callable<Object>() {

        @Override
        Object call() {
            int count = 0
            String url = 'http://localhost:8080/api/folders/aa330873-c3b1-4a33-a2ec-721e3197f744/profiles/unused'

            while (true) {
                HttpURLConnection connection = url.toURL().openConnection()
                connection.setRequestProperty('cookie', 'JSESSIONID=1829D907886ACA03E43A02C7C843DB2C')
                connection.setRequestMethod("GET");
                connection.connect()
                int code = connection.getResponseCode()

                if (code != 200) {
                    println("unused ${LocalDateTime.now()}: ${code} : ${connection.getErrorStream().text}")
                }
                count++
                if (count % 10 == 0) println "unused $count"
            }
            null
        }
    },
    new Callable<Object>() {

        @Override
        Object call() {
            int count = 0
            String url = 'http://localhost:8080/api/folders/aa330873-c3b1-4a33-a2ec-721e3197f744/permissions'

            while (true) {
                HttpURLConnection connection = url.toURL().openConnection()
                connection.setRequestProperty('cookie', 'JSESSIONID=1829D907886ACA03E43A02C7C843DB2C')
                connection.setRequestMethod("GET");
                connection.connect()
                int code = connection.getResponseCode()

                if (code != 200) {
                    println("permissions ${LocalDateTime.now()}: ${code} : ${connection.getErrorStream().text}")
                }
                count++
                if (count % 10 == 0) println "permissions $count"
            }
            null
        }
    },])
joe-crawford commented 2 years ago

About the permissions calls, mine are taking 10ms for the non-@ label folder, 80ms+ for the folder with the @, they're both in the same parent folder, calling them both repeatedly.

However I agree it isn't related to permissions actually because I have now seen the issue with your threaded script above, but changing both URLs to call the /profiles/unused endpoint. I'm seeing the error immediately when running the script, then all calls after that are succeeding.

Error is the same as before:

{
    "status": 500,
    "reason": "Internal Server Error",
    "errorCode": "UEX--",
    "message": "Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: update core.folder set version=?, date_created=?, last_updated=?, path=?, deleted=?, readable_by_authenticated_users=?, parent_folder_id=?, created_by=?, readable_by_everyone=?, label=?, description=? where id=? and version=?",
    "path": "/api/folders/c3100f09-f68d-47eb-93f3-4e18053a3822/profiles/unused",
    "environment": "DEVELOPMENT",
    "version": "5.1.0-SNAPSHOT",
    "exception": {
        "type": "StaleStateException",
        "message": "Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; statement executed: update core.folder set version=?, date_created=?, last_updated=?, path=?, deleted=?, readable_by_authenticated_users=?, parent_folder_id=?, created_by=?, readable_by_everyone=?, label=?, description=? where id=? and version=?",
        "stacktrace": [
            "org.hibernate.jdbc.Expectations$BasicExpectation.checkBatched(Expectations.java:67)",
            "org.hibernate.jdbc.Expectations$BasicExpectation.verifyOutcome(Expectations.java:54)",
            "org.hibernate.engine.jdbc.batch.internal.BatchingBatch.checkRowCounts(BatchingBatch.java:151)",
            "org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:126)",
            "org.hibernate.engine.jdbc.batch.internal.BatchingBatch.doExecuteBatch(BatchingBatch.java:106)",
            "org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.execute(AbstractBatchImpl.java:148)",
            "org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.executeBatch(JdbcCoordinatorImpl.java:198)",
            "org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:633)",
            "org.hibernate.engine.spi.ActionQueue.lambda$executeActions$1(ActionQueue.java:478)",
            "java.util.LinkedHashMap.forEach(LinkedHashMap.java:721)",
            "org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:475)",
            "org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:344)",
            "org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:40)",
            "org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:107)",
            "org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1416)",
            "org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:507)",
            "org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3299)",
            "org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2434)",
            "org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:449)",
            "org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:183)",
            "org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$300(JdbcResourceLocalTransactionCoordinatorImpl.java:40)",
            "org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:281)",
            "org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101)",
            "org.springframework.orm.hibernate5.HibernateTransactionManager.doCommit(HibernateTransactionManager.java:643)",
            "org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:743)",
            "org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711)",
            "org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:152)",
            "grails.gorm.transactions.GrailsTransactionTemplate.execute(GrailsTransactionTemplate.groovy:91)",
            "uk.ac.ox.softeng.maurodatamapper.profile.ProfileController.unusedProfiles(ProfileController.groovy:70)",
            "jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)",
            "org.grails.core.DefaultGrailsControllerClass$ReflectionInvoker.invoke(DefaultGrailsControllerClass.java:211)",
            "org.grails.core.DefaultGrailsControllerClass.invoke(DefaultGrailsControllerClass.java:188)",
            "org.grails.web.mapping.mvc.UrlMappingsInfoHandlerAdapter.handle(UrlMappingsInfoHandlerAdapter.groovy:90)",
            "org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067)",
            "org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)",
            "org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)",
            "org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)",
            "org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)",
            "org.grails.web.servlet.mvc.GrailsWebRequestFilter.doFilterInternal(GrailsWebRequestFilter.java:77)",
            "org.grails.web.filters.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:67)",
            "java.lang.Thread.run(Thread.java:833)"
        ]
    }
}
joe-crawford commented 2 years ago

I've also just seen the same error after changing both the URLs in the threaded script to just http://localhost:8080/api/folders with no ID.

olliefreeman commented 2 years ago

there has to be something in your database which the system is trying to update.

olliefreeman commented 2 years ago

can you run with grails run-app -Dlogging.sql=true -Dlogging.sql.parameters=true ... then find out what the parameters are that its feeding to the update command, and see how they differ from the current entry in the row in the actual db

basically what is update core.folder set version=?, date_created=?, last_updated=?, path=?, deleted=?, readable_by_authenticated_users=?, parent_folder_id=?, created_by=?, readable_by_everyone=?, label=?, description=? where id=? and version=? actually updating ... as i cant replicate it, the other option will be to drop a debug point in ProfileController.groovy:70 and trying to examine the state of the folder and why it might be being updated as part of the transaction

joe-crawford commented 2 years ago

This is testing with your threaded script with both URLs set to http://localhost:8080/api/folders/c3100f09-f68d-47eb-93f3-4e18053a3822.

Here is the SQL log from shortly before the exception is thrown:

2022-04-07 15:52:29,371 [80-exec-35] DEBUG org.hibernate.SQL                        : 
    update
        core.folder 
    set
        version=?,
        date_created=?,
        last_updated=?,
        path=?,
        deleted=?,
        readable_by_authenticated_users=?,
        parent_folder_id=?,
        created_by=?,
        readable_by_everyone=?,
        label=?,
        description=? 
    where
        id=? 
        and version=?
2022-04-07 15:52:29,371 [80-exec-35] TRACE o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [BIGINT] - [11150]
2022-04-07 15:52:29,371 [80-exec-35] TRACE o.h.type.descriptor.sql.BasicBinder      : binding parameter [2] as [TIMESTAMP] - [2022-04-07T12:46:13.476151+01:00]
2022-04-07 15:52:29,371 [80-exec-35] TRACE o.h.type.descriptor.sql.BasicBinder      : binding parameter [3] as [TIMESTAMP] - [2022-04-07T15:52:29.369816+01:00]
2022-04-07 15:52:29,371 [80-exec-35] TRACE o.h.type.descriptor.sql.BasicBinder      : binding parameter [4] as [LONGVARCHAR] - [fo:Profiles|fo:test@example.com]
2022-04-07 15:52:29,371 [80-exec-35] TRACE o.h.type.descriptor.sql.BasicBinder      : binding parameter [5] as [BOOLEAN] - [false]
2022-04-07 15:52:29,371 [80-exec-35] TRACE o.h.type.descriptor.sql.BasicBinder      : binding parameter [6] as [BOOLEAN] - [false]
2022-04-07 15:52:29,371 [80-exec-35] TRACE o.h.type.descriptor.sql.BasicBinder      : binding parameter [7] as [OTHER] - [1749ef72-f93d-4668-9747-c041ad2376f6]
2022-04-07 15:52:29,371 [80-exec-35] TRACE o.h.type.descriptor.sql.BasicBinder      : binding parameter [8] as [VARCHAR] - [admin@maurodatamapper.com]
2022-04-07 15:52:29,371 [80-exec-35] TRACE o.h.type.descriptor.sql.BasicBinder      : binding parameter [9] as [BOOLEAN] - [false]
2022-04-07 15:52:29,371 [80-exec-35] TRACE o.h.type.descriptor.sql.BasicBinder      : binding parameter [10] as [LONGVARCHAR] - [test@example.com]
2022-04-07 15:52:29,371 [80-exec-35] TRACE o.h.type.descriptor.sql.BasicBinder      : binding parameter [11] as [LONGVARCHAR] - [null]
2022-04-07 15:52:29,371 [80-exec-35] TRACE o.h.type.descriptor.sql.BasicBinder      : binding parameter [12] as [OTHER] - [c3100f09-f68d-47eb-93f3-4e18053a3822]
2022-04-07 15:52:29,371 [80-exec-35] TRACE o.h.type.descriptor.sql.BasicBinder      : binding parameter [13] as [BIGINT] - [11149]

Here are the database values exported from IntelliJ from after the error has occurred (possibly multiple times):

INSERT INTO core.folder
(id, version, date_created, last_updated, path, deleted, readable_by_authenticated_users, parent_folder_id, created_by, readable_by_everyone, label, description, class, branch_name, finalised, date_finalised, documentation_version, model_version, authority_id, model_version_tag)
VALUES
('c3100f09-f68d-47eb-93f3-4e18053a3822', 11184, '2022-04-07 12:46:13.476151', '2022-04-07 15:52:34.158745', 'fo:Profiles|fo:test@example.com', false, false, '1749ef72-f93d-4668-9747-c041ad2376f6', 'admin@maurodatamapper.com', false, 'test@example.com', null, 'uk.ac.ox.softeng.maurodatamapper.core.container.Folder', null, null, null, null, null, null, null);

So looks like the version and last_updated fields are updated.

joe-crawford commented 2 years ago

Just getting the folder URL http://localhost:8080/api/folders/c3100f09-f68d-47eb-93f3-4e18053a3822 normally in Postman, I can see it updates last_updated every time.

jamesrwelch commented 2 years ago

The updating of last_updated and version is also the root cause of #299

joe-crawford commented 2 years ago

The issue occurs due to parsing of paths containing labels which contain special characters:

As the path is stored as a string in the DB, using the above as special characters, sometimes there are ambiguous strings in paths, e.g. dc:test@example could reference a dataclass with label test@example, or a property example of the dataclass with label test. The StaleStateException occurs due to the ambiguous parsing of the paths leading to the resource path being marked as dirty in MdmDomain#setBuiltPath.

A full solution that would allow users to enter a label containing any of the special characters above would require an unambiguous parsing of the paths to labels and the special properties.

Temporary solutions may include prohibiting certain characters and special handling for others.

joe-crawford commented 2 years ago

Temporary solution: allow : as parsing of this is unambiguous, disallow the other special characters.