Closed robertoschwald closed 9 years ago
mumarm45 said: Now this problem has been increasing and three record insert per request [stackOverFolwQuestion|https://stackoverflow.com/questions/24241355/double-records-inserted-in-grails-using-audit-logging-plugin]
mumarm45 said: @Robert Oschwald Can you please help me on this issues.
roos said: See stackoverflow.
mumarm45 said: I have found the problem,I think, the problem is in plugin. My application uses three databases one is the main database and other two are for other purposes. My databSource is as following. || #TEST || #TEST1 || #TEST2 ||
|dataSource.driverClassName = net.sourceforge.jtds.jdbcx.JtdsDataSource dataSource.dbCreate = update dataSource.url = jdbc:jtds:sqlserver://localhost:1433/test dataSource.username = test dataSource.password = 123 | dataSource_TEST1.driverClassName = net.sourceforge.jtds.jdbcx.JtdsDataSource dataSource_TEST1.readOnly = true dataSource_TEST1.url = jdbc:jtds:sqlserver://xxx.xxx.xxx.xxx:1433/test1 dataSource_TEST1.username = test1 dataSource_TEST1.password = 123| |dataSource_TEST2.driverClassName = net.sourceforge.jtds.jdbcx.JtdsDataSource dataSource_TEST2.readOnly = true dataSource_TEST2.url = jdbc:jtds:sqlserver://192.168.200.151:1433/test2 dataSource_TEST2.username = test2 dataSource_TEST2.password = 123
When i use only the test datasource and remove other dataSources, it inserts one record. When i use two datasources then it insert two reocrd in audit logging table. Same as when i use the three datasources then it insert three record in audit logging. I need all three databases but it creates the problem. What should i do now?
roos said: I'll check the datasources related plugin code.
roos said: You can disable audit-log on a per-dataSource base if that is of help.
See http://grails.org/plugin/audit-logging chapter "Disable auditing by config"
roos said: Checked the audit-test test application with 3 configured DataStores. Tests passed, even in Grails 2.1.1 Events fire only for the datastore the Gorm operation was triggered in.
How exactly do you select the different dataSources?
roos said: Another question is: Do you use hibernate mapping files to configure DataSource to Domain class mappings? (grails-app/conf/hibernate/xxx_hibernate.cfg.xml files)? If yes, please check all of them that Domain classes do not occur in multiple config files.
mumarm45 said: I'm using external configuration for datasource, in my config file i'm doing this {quote}
grails.config.locations = [
"file:app-config.properties"]
] {quote} and datasource file is as following {quote} dataSource.driverClassName = net.sourceforge.jtds.jdbcx.JtdsDataSource dataSource.dbCreate = update dataSource.url = jdbc:jtds:sqlserver://localhost:1433/test dataSource.username = test dataSource.password = 123 dataSource.auditLog.disabled = false dataSource_TEST1.driverClassName = net.sourceforge.jtds.jdbcx.JtdsDataSource dataSource_TEST1.readOnly = true dataSource_TEST1.url = jdbc:jtds:sqlserver://xxx.xxx.xxx.xxx:1433/test1 dataSource_TEST1.username = test1 dataSource_TEST1.password = 123 _dataSourceTEST1.auditLog.disabled = true dataSource_TEST2.driverClassName = net.sourceforge.jtds.jdbcx.JtdsDataSource dataSource_TEST2.readOnly = true dataSource_TEST2.url = jdbc:jtds:sqlserver://xxx.xxx.xxx.xxxx:1433/test2 dataSource_TEST2.username = test2 dataSource_TEST2.password = 123 _dataSourceTEST2.auditLog.disabled = true {quote} But not work for me :( . When i use this dataSourcce file {quote} dataSource.driverClassName = net.sourceforge.jtds.jdbcx.JtdsDataSource dataSource.dbCreate = update dataSource.url = jdbc:jtds:sqlserver://localhost:1433/test dataSource.username = test dataSource.password = 123 {quote} and its insert only one record I'm not using hibernate mapping file.
roos said: It's part of the sources. See https://github.com/robertoschwald/grails-audit-logging-plugin
Simply run "grails perform-audit-log-test-apps" in the audit-test module dir.
If you want to integrate the source in an IDE (e.g. Intellij), perform
"grails integrate-with --intellij" as usual. See the Grails docu.
mumarm45 said: It's not working for me.
mirkt said: Today I noticed similar problem.. I was successfully running Grails (now 2.2.5) application for a long time, using audit-logging's (now 1.0.1) onSave, onDelete, onChange events to create/edit some objects, but I had to add second dataSource for some queries inside a controller (not for domain classes) and now objects created in onSave, onDelete, onChange events duplicates..
I do not define dataSource in my domain classes, because (http://grails.org/doc/2.2.1/guide/conf.html#multipleDatasources): .. If a domain class has no DataSource configuration, it defaults to the standard 'dataSource'. ..
My first dataSource uses Oracle, second MySQL if that makes any difference..
Any ideas?
svema said: Hi,
i have the same problem. I created a new grails 2.3.11 application. Added two domain classes, one with
{code} static mapping = { datasource 'demo' } {code}
Autogenerated controller and views.
Then i modified the DataSource.groovy
{code} development { dataSource { dbCreate = "create-drop" // one of 'create', 'create-drop', 'update', 'validate', '' url = "jdbc:h2:mem:devDb;MVCC=TRUE;LOCK_TIMEOUT=10000;DB_CLOSE_ON_EXIT=FALSE" }
dataSource_demo {
dbCreate = "create-drop" // one of 'create', 'create-drop', 'update', 'validate', ''
url = "jdbc:h2:mem:demoDb;MVCC=TRUE;LOCK_TIMEOUT=10000;DB_CLOSE_ON_EXIT=FALSE"
}
}
{code}
I also tested with: {code} development { dataSource { dbCreate = "create-drop" // one of 'create', 'create-drop', 'update', 'validate', '' url = "jdbc:h2:mem:devDb;MVCC=TRUE;LOCK_TIMEOUT=10000;DB_CLOSE_ON_EXIT=FALSE" }
dataSource_demo {
dbCreate = "create-drop" // one of 'create', 'create-drop', 'update', 'validate', ''
url = "jdbc:h2:mem:demoDb;MVCC=TRUE;LOCK_TIMEOUT=10000;DB_CLOSE_ON_EXIT=FALSE"
auditLog.disabled = true
}
}
{code}
In Config.groovy i added
{code} auditLog { verbose = true defaultIgnore = ['version', 'lastUpdated', 'lastUpdatedBy'] transactional = false defaultMask = ['ssn'] logIds = true defaultActor = 'SYS' } {code}
Adding a Person results in:
||ID||ACTOR||CLASS_NAME||DATE_CREATED||EVENT_NAME||LAST_UPDATED||NEW_VALUE||OLD_VALUE||PERSISTED_OBJECT_ID||PERSISTED_OBJECT_VERSION||PROPERTY_NAME||URI
|1|SYS|Person|2014-09-15 11:48:15.37|INSERT|2014-09-15 11:48:15.37|Max|null|1|null|firstname|null
|2|SYS|Person|2014-09-15 11:48:15.383|INSERT|2014-09-15 11:48:15.383|Mustermann|null|1|null|lastname|null
|3|SYS|Person|2014-09-15 11:48:15.39|INSERT|2014-09-15 11:48:15.39|Max|null|1|null|firstname|null
|4|SYS|Person|2014-09-15 11:48:15.395|INSERT|2014-09-15 11:48:15.395|Mustermann|null|1|null|lastname|null
mumarm45 said: Yes this plugin has this issue.
hollowaybrad said: I am having the same issue as well. Have used the plugin on previous projects with only one datasource and all worked. Now on a project with 2 datasources I get duplicate audit records created. Setting auditLog.disabled = true has not helped
hollowaybrad said: Sorry I should mention that I was previously using Grails 2.3.7 with plugin version 0.5.5.3 and a single data source project. My current double data source project where I am seeing this issue is using Grails 2.4.3 with plugin version 1.0.1. I attempted to set the version back to 0.5.5.3 and test if this issue exists there but I ran into incompatibilities with Hibernate 4, Grails 2.4.3 and version 0.5.5.3 of the plugin.
hollowaybrad said: Trying to provide more info I turned on logging in the plugin and I can see it happening twice:
{code} 2014-10-27 17:29:44,002 [http-bio-8080-exec-11] TRACE auditable.AuditLogListener - Audit logging: PreUpdate for com.domain.Official 2014-10-27 17:29:44,079 [http-bio-8080-exec-11] TRACE auditable.AuditLogListener - There are new and old values to log 2014-10-27 17:29:44,095 [http-bio-8080-exec-11] TRACE auditable.AuditLogListener - trimming object's string representation based on 255 characters. 2014-10-27 17:29:44,106 [http-bio-8080-exec-11] TRACE auditable.AuditLogListener - trimming object's string representation based on 255 characters. 2014-10-27 17:29:44,128 [http-bio-8080-exec-11] INFO auditable.AuditLogListener - audit log Mon Oct 27 17:29:44 EDT 2014 user bholloway UPDATE Official id:5 version:null 2014-10-27 17:29:44,309 [http-bio-8080-exec-11] TRACE auditable.AuditLogListener - calling execute handler ... 2014-10-27 17:29:44,309 [http-bio-8080-exec-11] TRACE auditable.AuditLogListener - ... execute handler is finished. 2014-10-27 17:29:44,310 [http-bio-8080-exec-11] TRACE auditable.AuditLogListener - Audit logging: PreUpdate for com.domain.Official 2014-10-27 17:29:44,311 [http-bio-8080-exec-11] TRACE auditable.AuditLogListener - There are new and old values to log 2014-10-27 17:29:44,311 [http-bio-8080-exec-11] TRACE auditable.AuditLogListener - trimming object's string representation based on 255 characters. 2014-10-27 17:29:44,313 [http-bio-8080-exec-11] INFO auditable.AuditLogListener - audit log Mon Oct 27 17:29:44 EDT 2014 user bholloway UPDATE Official id:5 version:null 2014-10-27 17:29:44,343 [http-bio-8080-exec-11] TRACE auditable.AuditLogListener - calling execute handler ... 2014-10-27 17:29:44,343 [http-bio-8080-exec-11] TRACE auditable.AuditLogListener - ... execute handler is finished. {code}
roos said: That is really strange, as we register an AuditLogListener per datasource. Looks like the onPersistenceEvent() is fired for both datasources.
Could you please provide a sample application which shows the error?
hollowaybrad said: I can try to put together a small sample app to test. In the meantime I copied the check for the AuditLogListener into BootStrap.groovy and it's not skipping the second datasource that is flagged with auditLog.disabled = true.
Edit: Its doesn't appear to find the disabled setting from the datasource. It looks as if the call to datastore.config.auditLog is finding the application auditLog config and not the datasource specific config. Maybe this will not work from BootStrap.groovy though, I am not sure. See output below
{code:title=BootStrap.groovy|borderStyle=solid} def grailsApplication
def init = { servletContext ->
grailsApplication.mainContext.eventTriggeringInterceptor.datastores.each { k, datastore -> println "############################################### Found datastore with key ${k}" println "########################################## datastore auditlog config is: ${datastore.config.auditLog}"
if (!grailsApplication.config.auditLog.disabled && !datastore.config.auditLog.disabled) { println "########################################## Registering a datastore with key ${k}" } }
} {code}
prints: {code:title=output|borderStyle=solid} ############################################### Found a datastore with key org.codehaus.groovy.grails.orm.hibernate.SessionFactoryProxy@6fd685 ########################################## datastore auditlog config is: [verbose:true, logIds:true, cacheDisabled:true, actorClosure:Config$_run_closure5_closure14@1f6e3e9, tablename:[:], largeValueColumnTypes:[:], disabled:[:], nonVerboseDelete:[:], transactional:[:], sessionAttribute:[:], actorKey:[:], truncateLength:[:], defaultIgnore:[:], defaultMask:[:], propertyMask:[:], replacementPatterns:[:]] ########################################## Registering a datastore with key org.codehaus.groovy.grails.orm.hibernate.SessionFactoryProxy@6fd685 ############################################### Found a datastore with key org.codehaus.groovy.grails.orm.hibernate.SessionFactoryProxy@438ef4 ########################################## datastore auditlog config is: [verbose:true, logIds:true, cacheDisabled:true, actorClosure:Config$_run_closure5_closure14@1f6e3e9, tablename:[:], largeValueColumnTypes:[:], disabled:[:], nonVerboseDelete:[:], transactional:[:], sessionAttribute:[:], actorKey:[:], truncateLength:[:], defaultIgnore:[:], defaultMask:[:], propertyMask:[:], replacementPatterns:[:]] ########################################## Registering a datastore with key org.codehaus.groovy.grails.orm.hibernate.SessionFactoryProxy@438ef4 {code}
{code:title=second datasource|borderStyle=solid} dataSourcecommon { pooled = true driverClassName ="com.ibm.as400.access.AS400JDBCDriver" dialect = "org.hibernate.dialect.DB2400Dialect" username = "***" password = "*_" auditLog.disabled = true properties { defaultAutoCommit="true" initialSize="10" logAbandoned="true" maxActive="100" maxIdle="10" maxWait="10000" minEvictableIdleTimeMillis="10000" minIdle="10" removeAbandoned="false" removeAbandonedTimeout="60" testOnBorrow="true" testOnReturn="false" testWhileIdle="false" timeBetweenEvictionRunsMillis="10000" validationInterval="30000" validationQuery="SELECT 1 FROM sysibm.sysdummy1" } }
{code}
roos said: In July we added to the audit-test test application [2 additional datasources|https://github.com/robertoschwald/grails-audit-logging-plugin/blob/master/audit-test/grails-app/conf/DataSource.groovy] but were unable to see such effect there. There must be some edge case which causes the problem.
hollowaybrad said: I don't see anywhere in the test code where it uses the auditLog.disabled = true setting in the datasource. Was it tested with this setting?
When I output the call to datastore.config in my Bootstrap.groovy test I get the config for the whole application not just the datasource. When I output datastore.config.auditLog I appear to get the auditLog config set at the application level and not the datasource level. Something appears to be wrong how its reading the datasource config properties. To access the auditLog.disabled property set in my datasource I have to call the datasource by name like : grailsApplication.config.dataSource_common.auditLog
Updated BootStrap.groovy:
{code:title=BootStrap.groovy|borderStyle=solid} def grailsApplication
def init = { servletContext ->
grailsApplication.mainContext.eventTriggeringInterceptor.datastores.each { k, datastore ->
println "############################################### Found a datastore with key ${k}"
println "########################################## datastore auditlog config is: ${datastore.config.auditLog}"
if (!grailsApplication.config.auditLog.disabled && !datastore.config.auditLog.disabled) {
println "########################################## Registering a datastore with key ${k}"
}
}
println""
println " ########################################## Got datasource config: ${grailsApplication.config.dataSource.auditLog}"
println " ########################################## Got datasource_common config: ${grailsApplication.config.dataSource_common.auditLog}"
}
{code}
Outputs:
{code} ############################################### Found a datastore with key org.codehaus.groovy.grails.orm.hibernate.SessionFactoryProxy@1b7c21 ########################################## datastore auditlog config is: [verbose:true, logIds:true, cacheDisabled:true, actorClosure:Config$_run_closure5_closure14@67ec05, tablename:[:], largeValueColumnTypes:[:], disabled:[:], nonVerboseDelete:[:], transactional:[:], sessionAttribute:[:], actorKey:[:], truncateLength:[:], defaultIgnore:[:], defaultMask:[:], propertyMask:[:], replacementPatterns:[:]] ########################################## Registering a datastore with key org.codehaus.groovy.grails.orm.hibernate.SessionFactoryProxy@1b7c21 ############################################### Found a datastore with key org.codehaus.groovy.grails.orm.hibernate.SessionFactoryProxy@1391509 ########################################## datastore auditlog config is: [verbose:true, logIds:true, cacheDisabled:true, actorClosure:Config$_run_closure5_closure14@67ec05, tablename:[:], largeValueColumnTypes:[:], disabled:[:], nonVerboseDelete:[:], transactional:[:], sessionAttribute:[:], actorKey:[:], truncateLength:[:], defaultIgnore:[:], defaultMask:[:], propertyMask:[:], replacementPatterns:[:]] ########################################## Registering a datastore with key org.codehaus.groovy.grails.orm.hibernate.SessionFactoryProxy@1391509 ########################################## Got datasource config: [:] ########################################## Got datasource_common config: [disabled:true] {code}
roos said: It's currently not testing for the disabled key. We added it to eventually see the effect of double written entries. It never happened. Test for the logged entries see AuditInsertSpec. There we check the size in the db. If there were any double written entries, one of the tests should have failed, but it didn't so far. Strange.
hollowaybrad said: Hmm. I guess I am confused how this auditLog.disabled = true setting in the datasource is working. If I output the class of this type in the datastores.each closure I get this:
grailsApplication.mainContext.eventTriggeringInterceptor.datastores.each { k, datastore -> println "datastore class is ${datastore.class}" = org.codehaus.groovy.grails.orm.hibernate.HibernateDatastore } if I output the class where it works and I get the auditLog.disabled property from the datasource its not a HibernateDatastore its a map: println "datasource_common class is ${grailsApplication.config.dataSource_common.class}" = [:]
The way the plugin is checking for the auditLog.disabled in the datasource its actually checking a HibernateDatastore objects config property, which appears to be the application config and not the datasource config, thus the disabled property is not there.
Is there a unit test or anything that validates that the auditLog.disabled = true in the datasource works as intended?
hollowaybrad said: Sorry in the previous example I left off the .config in my call to datastore.class. In this case they both return a map, however its still appears the map that is returned in the each closure is the config for the whole app and not the datasource. So I guess I am wondering if the "if" check in the AuditLoggingGrailsPlugin.groovy for datastore.config.auditLog.disabled will ever work:
{code} if (!application.config.auditLog.disabled && !datastore.config.auditLog.disabled) { {code}
Thanks for all of the responses by the way.
roos said: Please file a new ticket regarding disabled handling.
hollowaybrad said: Thanks I have registered a new ticket for the disabled handling.
I have looked through the code for the auditing and I don't quite understand how it wouldn't create a log record for each datasource by default. You said above that you register an AuditLogListener per datasource and I can see that happening in the plugin. So by default wouldn't one listener be created for each datasource and each listener fire and record duplicate records on any event? I couldn't see in the code anywhere that checks for a specific datasource or anything like that. Can you please help me understand how this is working?
Is it the fact that the listener gets passed a datasource in its constructor and only events on that datasource should fire the listener?
roos said: bq. Is it the fact that the listener gets passed a datasource in its constructor and only events on that datasource should fire the listener?
Exactly.
roos said: Ok. Can reproduce now. I'm looking into it when I got time.
roos said: Fixed in 1.0.3-SNAPSHOT. Please try and feedback here. We can release 1.0.3 short term if resolved. Thanks.
hollowaybrad said: Awesome thanks. I have installed the snapshot and it appears to be working. Only one strange error on start up now that I suspect is due to Java 6:
{code}
Oct 29, 2014 10:50:34 AM org.springsource.loaded.agent.Watcher determineChangesSince
SEVERE: FileWatcher caught serious error, see cause
java.lang.NoSuchFieldError: timeStamp239neverHappen1414594233359
at org.codehaus.groovy.grails.plugins.orm.auditable.AuditLogListenerUtil$$EOu5lF0J.clinit_(AuditLogListenerUtil.groovy)
at org.codehaus.groovy.grails.plugins.orm.auditable.AuditLogListenerUtil$$DOu5lF0J._clinit_(Unknown Source)
at org.codehaus.groovy.grails.plugins.orm.auditable.AuditLogListenerUtil.
I have been getting this since I updated to Grails 2.4.3:
{code} 2014-10-29 10:51:27,073 [Thread-9] INFO compiler.DirectoryWatcher - Exception while trying to load WatchServiceDirectoryWatcher (this is probably Java 6 and WatchService isn't available). Falling back to PollingDirectoryWatcher. java.lang.reflect.InvocationTargetException at java.lang.Thread.run(Thread.java:662) Caused by: java.lang.NoClassDefFoundError: java/nio/file/FileSystems ... 1 more Caused by: java.lang.ClassNotFoundException: java.nio.file.FileSystems at java.net.URLClassLoader$1.run(URLClassLoader.java:202) at java.net.URLClassLoader.findClass(URLClassLoader.java:190) at java.lang.ClassLoader.loadClass(ClassLoader.java:306) ... 1 more {code}
roos said: Not related to this bug. Please use the Stackoverflow or the Grails Google Discussion group. Jira is not a discussion forum. Thanks.
hollowaybrad said: I am sorry I should have stated that different. I understand this is not a discussion forum.
The top SEVERE message is now happening in the 1.0.3-SNAPSHOT upon startup but not in the 1.0.1 version I was using. Its an error directly related to the plugin:
at org.codehaus.groovy.grails.plugins.orm.auditable.AuditLogListenerUtil$$EOu5lF0J._clinit_(AuditLogListenerUtil.groovy)
Are you saying this is not related to the fix? The bottom message I posted as additional information that the fix for the snapshot might now cause this error related to a Java version.
svema said: Hi,
1.0.3-SNAPSHOT solves the problem in my 2.3.11 application.
Thank you!
roos said:
Brad, have you performed "grails clean"? If that doesn't help, please remove the Grails cache files in
hollowaybrad said: I have done grails clean and removed the cache files and I still get the same error on start up. As far as I can tell it doesn't seem to affect the running app. When I switch to Java 7 with grails 2.4.3 the error is gone. I believe it has to do with something that isn't available in Java 6 that its trying to use:
Oct 29, 2014 12:57:12 PM org.springsource.loaded.agent.Watcher determineChangesSince SEVERE: FileWatcher caught serious error, see cause
That's why I posted to Grails start up error above. I also get a weird Exception while trying to load WatchServiceDirectoryWatcher (this is probably Java 6 and WatchService isn't available). Falling back to PollingDirectoryWatcher. when starting Grails 2.4.3 and Java 6. So I assume they are related.
I am trying to get our server guys to upgrade java and this problem should go away. But it should be noted there is a severe error thrown with version 1.0.3-SNAPSHOT of the plugin, Java 6 and Grails 2.4.3. I see the latest Grails 2.4.4 has fixed some issue with reloading so I will upgrade and test.
roos said: I re-published 1.0.3-SNAPSHOT. Code is unchanged, but I built the plugin using Java 1.6 (shouldn't make a difference, since code-base is Java 1.5, but who knows...)
hollowaybrad said: That seems to have resolved it although I can't be 100% sure as the upgrade to Grails 2.4.4 seems to have broken the run-app in STS, so I am now running Grails from the command prompt :) Thanks for all of the help.
hollowaybrad said: I switched back to Grails 2.4.3 and it does appear to have fixed the problem when you recompiled in Java 6. Thanks again
mirkt said: Thank you! My problem fixed in 1.0.3-SNAPSHOT
Original Reporter: mumarm45 Environment: Not Specified Version: Grails-AuditLogging 1.0.1 Migrated From: http://jira.grails.org/browse/GPAUDITLOGGING-64
I have installed, audit-logging plugin into my grails application. The grails version is 2.1.1 and plugin version is 1.0.1. In my domain class, i have added the static auditable = true and in my controller when i'm doing this
{code} *def stopSurvey(Long id) { def survey = Survey.findById(params['stop']) survey.status = Survey.NO_RUNNING_SURVERY
{code}
This plugin insert double record against this transaction. ||id ||actor ||class_name ||date_created ||event_name ||last_updated ||new_value ||old_value ||persisted_object_id ||persisted_object_version ||property_name ||uri |61 |admin |Survey |2014-06-13 18:10:02.2270000 |UPDATE |2014-06-13 18:10:02.2270000 |NULL |1 |1 |NULL |status NULL| |62 |admin |Survey |2014-06-13 18:10:02.5100000 |UPDATE |2014-06-13 18:10:02.5100000 |NULL |1 |1 |NULL |status NULL|