Concurrent modification exception
123 views
Skip to first unread message
Jake Foobar
May 20, 2021, 9:26:16 AM5/20/21
to inception-users
Hi,
We are running latest release 0.19.3 in MS Azure docker container, storage is mounted Azure file system.
As soon as an annotation is performed on doc, a 'concurrent modification' warning pops up:
'
Error: IOException: Detected concurrent modification to file in storage (expected timestamp: X; actual timestamp in storage Y) - please try reloading before saving again',
where X < Y.
Jake Foobar
May 20, 2021, 10:03:53 AM5/20/21
to inception-users
Inception logs from Azure:
021-05-20T13:10:22.697323813Z 2021-05-20 13:10:22 ERROR [XXXXX] ApplicationPageBase - XXXXX: Error: IOException: Detected concurrent modification to file in storage (expected timestamp: 1621516135194; actual timestamp in storage 1621516135312) - please try reloading before saving again.
2021-05-20T13:10:35.659990684Z 2021-05-20 13:10:35 ERROR [
XXXXX ] AnnotationDetailEditorPanel - Error: Detected concurrent modification to file in storage (expected timestamp: 1621516135194; actual timestamp in storage 1621516135312) - please try reloading before saving again.
2021-05-20T13:10:35.660029484Z java.io.IOException: Detected concurrent modification to file in storage (expected timestamp: 1621516135194; actual timestamp in storage 1621516135312) - please try reloading before saving again.
2021-05-20T13:10:35.660036184Z at de.tudarmstadt.ukp.clarin.webanno.api.dao.CasMetadataUtils.failOnConcurrentModification(CasMetadataUtils.java:79) ~[inception-api-dao-0.19.3.jar!/:?]
2021-05-20T13:10:35.660040984Z at de.tudarmstadt.ukp.clarin.webanno.api.dao.CasStorageServiceImpl.realWriteCas(CasStorageServiceImpl.java:296) ~[inception-api-dao-0.19.3.jar!/:?]
2021-05-20T13:10:35.660045384Z at de.tudarmstadt.ukp.clarin.webanno.api.dao.CasStorageServiceImpl.writeCas(CasStorageServiceImpl.java:238) ~[inception-api-dao-0.19.3.jar!/:?]
2021-05-20T13:10:35.660049884Z at de.tudarmstadt.ukp.clarin.webanno.api.dao.CasStorageServiceImpl$$FastClassBySpringCGLIB$$12470a1c.invoke(<generated>) ~[inception-api-dao-0.19.3.jar!/:?]
2021-05-20T13:10:35.660054784Z at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.3.3.jar!/:5.3.3]
2021-05-20T13:10:35.660059084Z at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688) ~[spring-aop-5.3.3.jar!/:5.3.3]
2021-05-20T13:10:35.660063184Z at de.tudarmstadt.ukp.clarin.webanno.api.dao.CasStorageServiceImpl$$EnhancerBySpringCGLIB$$fe17af45.writeCas(<generated>) ~[inception-api-dao-0.19.3.jar!/:?]
2021-05-20T13:10:35.660067584Z at de.tudarmstadt.ukp.clarin.webanno.api.dao.DocumentServiceImpl.writeAnnotationCas(DocumentServiceImpl.java:756) ~[inception-api-dao-0.19.3.jar!/:?]
2021-05-20T13:10:35.660071684Z at de.tudarmst
Jake Foobar
May 20, 2021, 10:05:09 AM5/20/21
to inception-users
By the way, same document loads fine on local standalone Inception install and annotation works as well.
Jake Foobar
May 20, 2021, 10:10:22 AM5/20/21
to inception-users
Using external MariaDB
Jan-Christoph Klie
May 20, 2021, 10:11:14 AM5/20/21
to inception-users
Hi,
we check via file change timestamps whether the file has been rewritten by another user while you were annotating. The problem now is that Azure Storage does not report valid monotonically increasing timestamps. See also [1] and [2]. Maybe Richard knows whether there is an actual way around INCEpTION reporting these errors.
Best,
Jan
Jan-Christoph Klie
May 20, 2021, 10:12:07 AM5/20/21
to inception-users
One addition:
We do not store annotations in the database but on disks as UIMA binary CAS files.
richard...@gmail.com
May 20, 2021, 10:56:20 AM5/20/21
to incepti...@googlegroups.com
Another user has observed the same issue and reported that it had disappeared after switching to a proper VM with a proper virtual hard disk. If search our issue tracker on GitHub for azure you will probably find the report as well as a link to an upstream issue the user has opened with Azure.
That said - what difference in the timestamps do you observe?
— Richard
Sent from my mobile, sorry for brevity.
Am 20.05.2021 um 15:26 schrieb Jake Foobar <himala...@gmail.com>:
Hi,
--
You received this message because you are subscribed to the Google Groups "inception-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to inception-use...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/inception-users/19f28703-b5a8-4681-8d0d-5b182458d534n%40googlegroups.com.
Message has been deleted
Jake Foobar
May 21, 2021, 8:21:01 AM5/21/21
to inception-users
Hi,
Invariably, expected timestamp < actual timestamp. That said, we ran through a few deployment scenarios and discovered that the defect does not occur in Inception versions 0.17.3 and earlier (we tried versions 0.16.XX and up). Defect is first observed in 0.17.4. Hopefully, that will be of help in pinpointing the root cause.
Reply all
Reply to author
Forward
Richard Eckart de Castilho
May 21, 2021, 8:21:49 AM5/21/21
to incepti...@googlegroups.com
On 21. May 2021, at 14:20, Jake Foobar <himala...@gmail.com> wrote:
>
> Invariable, expected timestamp < actual timestamp. That said, we ran through a few deployment scenarios and discovered that the defect does not occur in Inception versions 0.17.3 and earlier (we tried versions 0.16.XX and up). Defect is first observed in 0.17.4. Hopefully, that will be of help in pinpointing the root cause.
"expected timestamp < actual timestamp" is clear, but how much is the difference?
Is it a constant difference?
Is is seconds, minutes, hours, days, weeks...?
-- Richard
>
> Invariable, expected timestamp < actual timestamp. That said, we ran through a few deployment scenarios and discovered that the defect does not occur in Inception versions 0.17.3 and earlier (we tried versions 0.16.XX and up). Defect is first observed in 0.17.4. Hopefully, that will be of help in pinpointing the root cause.
"expected timestamp < actual timestamp" is clear, but how much is the difference?
Is it a constant difference?
Is is seconds, minutes, hours, days, weeks...?
-- Richard
Jake Foobar
May 21, 2021, 9:03:03 AM5/21/21
to inception-users
Exception timestamps are reported in milliseconds. Reported discrepancy is a less than 1 sec. Do not know if it's constant across exceptions
Jake Foobar
May 21, 2021, 9:05:17 AM5/21/21
to inception-users
Repeating one exception below:
2021-05-20T13:10:35.659990684Z 2021-05-20 13:10:35 ERROR [ XXXXX ] AnnotationDetailEditorPanel - Error: Detected concurrent modification to file in storage (expected timestamp: 1621516135194; actual timestamp in storage 1621516135312) - please try reloading before saving again.
Jake Foobar
May 21, 2021, 9:13:38 AM5/21/21
to inception-users
Timestamp discrepancy issue does disappear when if a Azure VM with attached storage. However, this deployment architecture has drawbacks - VM needs to be running 24X7 (higher cost) and disk space cannot be scaled up seamlessly
Howard Lander
Jan 12, 2022, 10:38:37 AM1/12/22
to inception-users
Hi all
We are seeing a somewhat similar problem on version 21.3: We are using a dedicated VM, but the file system is NFS mounted. Maybe that's the issue? If it matters (and I suppose it might) the user is VPNed in from Bangalore to our machine in North Carolina
Our error logs look like:
2022-01-12 06:44:43 ERROR [xxxxxx] ApplicationPageBase - xxxxxx: Error: IOException: There was a concurrent modification to the annotation CAS for user [xxxxxx] in document [PMC5231336.txt](663) (expected: 2022-01-12 06:44:39.159 actual on storage: 2022-01-12 06:44:39.160, delta: 00:00:00.001)
2022-01-12 06:44:58 ERROR [xxxxxx] BratAnnotationEditor - Error: IOException: There was a concurrent modification to the annotation CAS for user [xxxxxx] in document [PMC5231336.txt](663) (expected: 2022-01-12 06:44:39.159 actual on storage: 2022-01-12 06:44:39.160, delta: 00:00:00.001)
java.io.IOException: There was a concurrent modification to the annotation CAS for user [xxxxxxx] in document [PMC5231336.txt](663) (expected: 2022-01-12 06:44:39.159 actual on storage: 2022-01-12 06:44:39.160, delta: 00:00:00.001)Any ideas appreciated.
Howard
Richard Eckart de Castilho
Jan 12, 2022, 1:31:02 PM1/12/22
to incepti...@googlegroups.com
Hi,
what INCEpTION does when saving the annotation data is that it asks the file system after the save is complete for the last modification timestamp of the file and remembers that timestamp. When it then saves the data again *after* a user has performed some action, it asks the filesystem again for the last modification time *before* it overwrites the old data. If the remembered timestamp is different from the one reported by the file system now, it produces this error because it looks like some other process/thread has modified the file in between and that could mean that overwriting the data on disk could overwrite update data which would then be lost. So if the filesystem reports for the same file first "06:44:39.159" and then "06:44:39.160" without any concurrent process/thread having made any modification, then to me it looks like an issue with the file system.
The fix would probably be to change INCEpTION to not rely on the timestamps of the file system, but rather to use a different way of checking if a file on disk may have been
subject to a concurrent update - maybe by storing a timestamp or a serial number in a second file next to the primary data file.
It could of course be that we have a yet undiscovered bug in INCEpTION that updates are written to disk when they shouldn't be... running the system with the log level for `de.tudarmstadt.ukp.clarin.webanno.api.dao.casstorage.FileSystemCasStorageDriver` set to `trace` might help shedding some light on that.
You could add the "-Dlog4j.configurationFile=/path/to/log4j2.xml" as a command line argument when you start up INCEpTION and point it to the location where you place the attached log4j2.xml file is. It turns up the logging for the annotation storage up so we should be able to see all in-app accesses in the log this way. Maybe that provides an idea where this concurrent access could come from (assuming it comes from in-app).
Best,
-- Richard
what INCEpTION does when saving the annotation data is that it asks the file system after the save is complete for the last modification timestamp of the file and remembers that timestamp. When it then saves the data again *after* a user has performed some action, it asks the filesystem again for the last modification time *before* it overwrites the old data. If the remembered timestamp is different from the one reported by the file system now, it produces this error because it looks like some other process/thread has modified the file in between and that could mean that overwriting the data on disk could overwrite update data which would then be lost. So if the filesystem reports for the same file first "06:44:39.159" and then "06:44:39.160" without any concurrent process/thread having made any modification, then to me it looks like an issue with the file system.
The fix would probably be to change INCEpTION to not rely on the timestamps of the file system, but rather to use a different way of checking if a file on disk may have been
subject to a concurrent update - maybe by storing a timestamp or a serial number in a second file next to the primary data file.
It could of course be that we have a yet undiscovered bug in INCEpTION that updates are written to disk when they shouldn't be... running the system with the log level for `de.tudarmstadt.ukp.clarin.webanno.api.dao.casstorage.FileSystemCasStorageDriver` set to `trace` might help shedding some light on that.
You could add the "-Dlog4j.configurationFile=/path/to/log4j2.xml" as a command line argument when you start up INCEpTION and point it to the location where you place the attached log4j2.xml file is. It turns up the logging for the annotation storage up so we should be able to see all in-app accesses in the log this way. Maybe that provides an idea where this concurrent access could come from (assuming it comes from in-app).
Best,
-- Richard
Howard Lander
Jan 12, 2022, 2:56:19 PM1/12/22
to inception-users
Hi Richard,
Thanks for the reply. If I am reading this right, the difference is one thousandth of a second. Still kind of a weird thing for a file system to do though, but I guess it's possible. We'll upgrade to the latest version, crank up the logging and let you know if we see it again.
Thanks much
Howard
Richard Eckart de Castilho
Jan 12, 2022, 3:48:27 PM1/12/22
to incepti...@googlegroups.com
Hi Howard
> On 12. Jan 2022, at 20:56, Howard Lander <how...@renci.org> wrote:
>
> Thanks for the reply. If I am reading this right, the difference is one thousandth of a second. Still kind of a weird thing for a file system to do though, but I guess it's possible. We'll upgrade to the latest version, crank up the logging and let you know if we see it again.
I'll include a slightly improved logging message in the upcoming INCEpTION 22.1 which logs the timestamp when writing the data to disk - so hopefully we should be easier able to see if the timestamp when the data was written really differs from the timestamp when the data is checked or if another spurious update happens.
----
2022-01-12 21:44:21 [http-nio-8080-exec-6] DEBUG [admin] FileSystemCasStorageDriver - Updated annotations for user [CURATION_USER] on document [de-universal-dev.tsv](1443) in project [demo-anno-de](260) in 10ms (file timestamp: 2022-01-12 21:44:21.518)
----
Cheers,
-- Richard
> On 12. Jan 2022, at 20:56, Howard Lander <how...@renci.org> wrote:
>
> Thanks for the reply. If I am reading this right, the difference is one thousandth of a second. Still kind of a weird thing for a file system to do though, but I guess it's possible. We'll upgrade to the latest version, crank up the logging and let you know if we see it again.
----
2022-01-12 21:44:21 [http-nio-8080-exec-6] DEBUG [admin] FileSystemCasStorageDriver - Updated annotations for user [CURATION_USER] on document [de-universal-dev.tsv](1443) in project [demo-anno-de](260) in 10ms (file timestamp: 2022-01-12 21:44:21.518)
----
Cheers,
-- Richard
Howard Lander
Jan 13, 2022, 1:16:31 PM1/13/22
to inception-users
Hi Richard
I've restarted with version 22.1 and the logging file you provided. I added the -D stanza to inception.conf, which now looks like:
JAVA_OPTS="-Dlog4j.configurationFile=/projects/neurobridges/inception/log4j2.xml -Djava.awt.headless=true -Xmx4g -Dinception.home=/projects/neurobridges/inception"
which I think should do what we want. I'll let you know if we see any more anomalies.
Thanks
Howard
Reply all
Reply to author
Forward
0 new messages