improve logging on vetos

Yoann Delattre
1 day ago
Hi Everyone !
I get this error when i run a SQL loader :
grouper-daemon;grouper_error.log;2023-03-06T09:47:42,258: [DefaultQuartzScheduler_Worker-5] ERROR GrouperLoaderJob.runJob(560) - [] - Error on job: SQL_GROUP_LIST_etc:tache-synchronisation:services:direction_bc061937a05f486aa79e07d164ea50bc
edu.internet2.middleware.grouper.hooks.logic.HookVeto: veto.stem.unique.nameCaseInsensitive: Le nom du dossier est déjà utilisé, veuillez utiliser un autre nom
at edu.internet2.middleware.grouper.hooks.examples.StemUniqueNameCaseInsensitiveHook.verifyCaseInsensitiveName(StemUniqueNameCaseInsensitiveHook.java:124) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.hooks.examples.StemUniqueNameCaseInsensitiveHook.stemPreUpdate(StemUniqueNameCaseInsensitiveHook.java:139) ~[grouper-2.6.18.jar:2.6.18]
at sun.reflect.GeneratedMethodAccessor2089.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_352]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_352]
at edu.internet2.middleware.grouper.util.GrouperUtil.invokeMethod(GrouperUtil.java:5415) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.hooks.logic.GrouperHooksUtils.executeHook(GrouperHooksUtils.java:509) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.hooks.logic.GrouperHooksUtils.callHooksIfRegistered(GrouperHooksUtils.java:309) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.hooks.logic.GrouperHooksUtils.callHooksIfRegistered(GrouperHooksUtils.java:248) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.hooks.logic.GrouperHooksUtils.callHooksIfRegistered(GrouperHooksUtils.java:174) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.Stem.onPreUpdate(Stem.java:3868) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.hibernate.ByObject.update(ByObject.java:613) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.hibernate.ByObjectStatic$2.callback(ByObjectStatic.java:214) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.hibernate.HibernateSession.callbackHibernateSession(HibernateSession.java:722) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.hibernate.ByObjectStatic.update(ByObjectStatic.java:199) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3StemDAO.update(Hib3StemDAO.java:1177) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.Stem$4.callback(Stem.java:1971) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.hibernate.HibernateSession.callbackHibernateSession(HibernateSession.java:722) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.Stem.store(Stem.java:1958) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.StemSave$1$1.callback(StemSave.java:582) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.GrouperSession.callbackGrouperSession(GrouperSession.java:1000) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.StemSave$1.callback(StemSave.java:604) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3TransactionDAO$1.callback(Hib3TransactionDAO.java:66) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.hibernate.HibernateSession.callbackHibernateSession(HibernateSession.java:722) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.internal.dao.hib3.Hib3TransactionDAO.transactionCallback(Hib3TransactionDAO.java:56) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.hibernate.GrouperTransaction.callbackGrouperTransaction(GrouperTransaction.java:87) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.hibernate.GrouperTransaction.callbackGrouperTransaction(GrouperTransaction.java:106) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.StemSave.save(StemSave.java:375) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType.syncFolderList(GrouperLoaderType.java:2263) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType.syncGroupList(GrouperLoaderType.java:1992) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.app.loader.GrouperLoaderType$5.runJob(GrouperLoaderType.java:575) ~[grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.runJob(GrouperLoaderJob.java:541) [grouper-2.6.18.jar:2.6.18]
at edu.internet2.middleware.grouper.app.loader.GrouperLoaderJob.execute(GrouperLoaderJob.java:345) [grouper-2.6.18.jar:2.6.18]
at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [quartz-2.3.2.jar:?]
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [quartz-2.3.2.jar:?]
But the folder name is not in the stack trace :smiling_face_with_tear:
I read that it was supposed to be fixed in 2.6.1 (GRP-3665).
I used Grouper v2.6.18.
Thanks.

Carey Black
1 day ago
After reading that patch ( GRP-3665 ) I am not sure it would improve the logging if the group name was the thing that caught the hook. :thinking_face:
However the exception listed does say "stem" too.
Have you looked for "Problem creating child stem:" in the full log?
That looks like what the GRP should have added as a prefix to the error string that should have the name in it.

Yoann Delattre
1 day ago
I just tried : no result.
Seems the patch is not working as expected :-/
Maybe it's possible to had a variable in grouperText properties ? Something like that :
veto.stem.unique.nameCaseInsensitive.default = The folder name $stemName$ is already in use, please use a different name

Chris Hyzer
23 hours ago
we can improve the logging... in the meantime can you look at alternate names in your grouper_stems table and see if one exists that you think the loader is creating?

Chris Hyzer
23 hours ago
also is there more to the stack in the logs? can you post any more that is in the logs?
New

Yoann Delattre
7 hours ago
After some time, i found the problematic stems but it was a little painful :sweat_smile:
So, a big YES if you can improve the logging.
Sorry, i have nothing else in the logs :confused: