I'm trying to delete a persistent object that consists of a composite key and a set of objects. The delete works, but on careful inspection of the logs it seems that Hibernate is deleting the sets for other objects of the same type and then reinserting them. The only clue I've been able to find are lines like this in the hibernate debug output
Code:
2005-10-27 10:49:09,827 95036 DEBUG [http-8080-Processor18] org.hibernate.event.def.WrapVisitor (WrapVisitor.java:87) - Wrapped collection in role: com.contentconnections.revman.course.InstructorInfluences.influenceFunctions
2005-10-27 10:49:09,827 95036 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=2, courseId=4}], was: [<unreferenced>] (initialized)
2005-10-27 10:49:09,828 95037 DEBUG [http-8080-Processor18] org.hibernate.event.def.WrapVisitor (WrapVisitor.java:87) - Wrapped collection in role: com.contentconnections.revman.course.InstructorInfluences.influenceFunctions
2005-10-27 10:49:09,829 95038 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=1, courseId=4}], was: [<unreferenced>] (initialized)
I have no idea what the "was [<unreferenced>]" part means, but it must be the reason that the collections are being deleted because that is closely followed by:
Code:
2005-10-27 10:49:09,840 95049 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:209) - Processing unreferenced collections
2005-10-27 10:49:09,840 95049 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:50) - Collection dereferenced: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=3, courseId=4}]
2005-10-27 10:49:09,841 95050 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:50) - Collection dereferenced: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=2, courseId=4}]
2005-10-27 10:49:09,842 95051 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:50) - Collection dereferenced: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=1, courseId=4}]
2005-10-27 10:49:09,842 95051 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:223) - Scheduling collection removes/(re)creates/updates
2005-10-27 10:49:09,845 95054 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:85) - Flushed: 0 insertions, 0 updates, 1 deletions to 16 objects
2005-10-27 10:49:09,846 95055 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:91) - Flushed: 2 (re)creations, 0 updates, 3 removals to 20 collections
So, can anyone tell me what the [<unreferenced>] part means and maybe whats causing it?
Thanks.
Hibernate version: 3.0.5
Mapping documents:Code:
<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping>
<class name="com.contentconnections.revman.course.InstructorInfluences" table="revman_course_instructors">
<composite-id name="id" class="com.contentconnections.revman.course.CourseInstructorCompositeId">
<key-property name="courseId" />
<key-property name="instructorId" />
</composite-id>
<many-to-one name="course" class="com.contentconnections.revman.course.Course" column="courseId" insert="false" update="false" />
<many-to-one name="instructor" class="com.contentconnections.revman.contact.Contact" column="instructorId" insert="false" update="false" />
<set name="influenceFunctions" table="revman_course_instructor_influence_functions">
<key>
<column name="courseId" />
<column name="instructorId" />
</key>
<many-to-many column="influenceFunctionId" class="com.contentconnections.revman.course.InfluenceFunction"/>
</set>
</class>
</hibernate-mapping>
[b]Code between sessionFactory.openSession() and session.close():[/b]
Full stack trace of any exception that occurs:N/A
Name and version of the database you are using:MySQL 4.1.14
The generated SQL (show_sql=true):Debug level Hibernate log excerpt:Code:
2005-10-27 10:49:09,764 94973 DEBUG [http-8080-Processor18] org.hibernate.impl.SessionImpl (SessionImpl.java:1169) - setting flush mode to: AUTO
2005-10-27 10:49:09,765 94974 DEBUG [http-8080-Processor18] org.hibernate.transaction.JDBCTransaction (JDBCTransaction.java:54) - begin
2005-10-27 10:49:09,765 94974 DEBUG [http-8080-Processor18] org.hibernate.transaction.JDBCTransaction (JDBCTransaction.java:59) - current autocommit status: true
2005-10-27 10:49:09,766 94975 DEBUG [http-8080-Processor18] org.hibernate.transaction.JDBCTransaction (JDBCTransaction.java:62) - disabling autocommit
2005-10-27 10:49:09,766 94975 DEBUG [http-8080-Processor18] org.hibernate.jdbc.JDBCContext (JDBCContext.java:187) - before transaction completion
2005-10-27 10:49:09,768 94977 DEBUG [http-8080-Processor18] org.springframework.aop.interceptor.CustomizableTraceInterceptor (CustomizableTraceInterceptor.java:268) - entering CourseServiceDefaultImpl.removeInstructor(Course,Contact) - args = com.contentconnections.revman.course.Course@445dcf[id=4,actualTitle=Calc I,courseNumber=MAT200,termOffered=7,commonName=com.contentconnections.revman.course.CourseCommonName@12149c5[id=1,name=Linear Algebra,description=],enrollment=0,institution=com.contentconnections.revman.Institution@c6552a[id=1,name=Arizona State University,types=[com.contentconnections.revman.InstitutionType@9868b6[id=2,name=4-year,description=]],enrollment=0,address=com.contentconnections.revman.contact.Address@2925e[id=<null>,street=,street2=,city=,province=,postalCode=,country=],url=,phone=,directoryUrl=,catalogUrl=],department=com.contentconnections.revman.Department@10163e1[id=1,name=Math,phone=,url=,enrollment=0,institution=com.contentconnections.revman.Institution@c6552a[id=1,name=Arizona State University,types=[com.contentconnections.revman.InstitutionType@9868b6[id=2,name=4-year,description=]],enrollment=0,address=com.contentconnections.revman.contact.Address@2925e[id=<null>,street=,street2=,city=,province=,postalCode=,country=],url=,phone=,directoryUrl=,catalogUrl=]],hotLead=false,hotLeadComments=,adoptionDecision=3],com.contentconnections.revman.contact.Contact@ed9cd5[id=3,salutation=1,firstName=Q,lastName=A,gender=M,title=com.contentconnections.revman.contact.ContactTitle@18657b9[id=1,title=Department Head,priority=1,description=],discipline=,email=,address=com.contentconnections.revman.contact.Address@e95a72[id=<null>,street=,street2=,city=,province=,postalCode=,country=],primaryPhone=,altPhone=,optInTypes=[],decisionMaker=false,notes=]
2005-10-27 10:49:09,769 94978 DEBUG [http-8080-Processor18] org.springframework.aop.interceptor.CustomizableTraceInterceptor (CustomizableTraceInterceptor.java:268) - entering CourseDaoHibernateSpringImpl.getInstructorInfluences(CourseInstructorCompositeId) - args = com.contentconnections.revman.course.CourseInstructorCompositeId@15c46b5[courseId=4,instructorId=3]
2005-10-27 10:49:09,770 94979 DEBUG [http-8080-Processor18] org.hibernate.event.def.DefaultLoadEventListener (DefaultLoadEventListener.java:153) - loading entity: [com.contentconnections.revman.course.InstructorInfluences#component[courseId,instructorId]{instructorId=3, courseId=4}]
2005-10-27 10:49:09,771 94980 DEBUG [http-8080-Processor18] org.hibernate.event.def.DefaultLoadEventListener (DefaultLoadEventListener.java:304) - attempting to resolve: [com.contentconnections.revman.course.InstructorInfluences#component[courseId,instructorId]{instructorId=3, courseId=4}]
2005-10-27 10:49:09,775 94984 DEBUG [http-8080-Processor18] org.hibernate.event.def.DefaultLoadEventListener (DefaultLoadEventListener.java:313) - resolved object in session cache: [com.contentconnections.revman.course.InstructorInfluences#component[courseId,instructorId]{instructorId=3, courseId=4}]
2005-10-27 10:49:09,781 94990 DEBUG [http-8080-Processor18] org.springframework.aop.interceptor.CustomizableTraceInterceptor (CustomizableTraceInterceptor.java:280) - exiting CourseDaoHibernateSpringImpl.getInstructorInfluences(CourseInstructorCompositeId) - returning com.contentconnections.revman.course.InstructorInfluences@ca6359[id=com.contentconnections.revman.course.CourseInstructorCompositeId@ee1c42[courseId=4,instructorId=3],course=com.contentconnections.revman.course.Course@445dcf[id=4,actualTitle=Calc I,courseNumber=MAT200,termOffered=7,commonName=com.contentconnections.revman.course.CourseCommonName@12149c5[id=1,name=Linear Algebra,description=],enrollment=0,institution=com.contentconnections.revman.Institution@c6552a[id=1,name=Arizona State University,types=[com.contentconnections.revman.InstitutionType@9868b6[id=2,name=4-year,description=]],enrollment=0,address=com.contentconnections.revman.contact.Address@2925e[id=<null>,street=,street2=,city=,province=,postalCode=,country=],url=,phone=,directoryUrl=,catalogUrl=],department=com.contentconnections.revman.Department@10163e1[id=1,name=Math,phone=,url=,enrollment=0,institution=com.contentconnections.revman.Institution@c6552a[id=1,name=Arizona State University,types=[com.contentconnections.revman.InstitutionType@9868b6[id=2,name=4-year,description=]],enrollment=0,address=com.contentconnections.revman.contact.Address@2925e[id=<null>,street=,street2=,city=,province=,postalCode=,country=],url=,phone=,directoryUrl=,catalogUrl=]],hotLead=false,hotLeadComments=,adoptionDecision=3],instructor=com.contentconnections.revman.contact.Contact@ed9cd5[id=3,salutation=1,firstName=Q,lastName=A,gender=M,title=com.contentconnections.revman.contact.ContactTitle@18657b9[id=1,title=Department Head,priority=1,description=],discipline=,email=,address=com.contentconnections.revman.contact.Address@e95a72[id=<null>,street=,street2=,city=,province=,postalCode=,country=],primaryPhone=,altPhone=,optInTypes=[],decisionMaker=false,notes=],influenceFunctions=[com.contentconnections.revman.course.InfluenceFunction@1829770[id=2,name=Decision Influencer,description=Holds sway over those making the decision,points=4], com.contentconnections.revman.course.InfluenceFunction@a4461e[id=4,name=Committee Member,description=,points=3]]]
2005-10-27 10:49:09,783 94992 DEBUG [http-8080-Processor18] org.springframework.aop.interceptor.CustomizableTraceInterceptor (CustomizableTraceInterceptor.java:268) - entering CourseDaoHibernateSpringImpl.remove(InstructorInfluences) - args = com.contentconnections.revman.course.InstructorInfluences@ca6359[id=com.contentconnections.revman.course.CourseInstructorCompositeId@ee1c42[courseId=4,instructorId=3],course=com.contentconnections.revman.course.Course@445dcf[id=4,actualTitle=Calc I,courseNumber=MAT200,termOffered=7,commonName=com.contentconnections.revman.course.CourseCommonName@12149c5[id=1,name=Linear Algebra,description=],enrollment=0,institution=com.contentconnections.revman.Institution@c6552a[id=1,name=Arizona State University,types=[com.contentconnections.revman.InstitutionType@9868b6[id=2,name=4-year,description=]],enrollment=0,address=com.contentconnections.revman.contact.Address@2925e[id=<null>,street=,street2=,city=,province=,postalCode=,country=],url=,phone=,directoryUrl=,catalogUrl=],department=com.contentconnections.revman.Department@10163e1[id=1,name=Math,phone=,url=,enrollment=0,institution=com.contentconnections.revman.Institution@c6552a[id=1,name=Arizona State University,types=[com.contentconnections.revman.InstitutionType@9868b6[id=2,name=4-year,description=]],enrollment=0,address=com.contentconnections.revman.contact.Address@2925e[id=<null>,street=,street2=,city=,province=,postalCode=,country=],url=,phone=,directoryUrl=,catalogUrl=]],hotLead=false,hotLeadComments=,adoptionDecision=3],instructor=com.contentconnections.revman.contact.Contact@ed9cd5[id=3,salutation=1,firstName=Q,lastName=A,gender=M,title=com.contentconnections.revman.contact.ContactTitle@18657b9[id=1,title=Department Head,priority=1,description=],discipline=,email=,address=com.contentconnections.revman.contact.Address@e95a72[id=<null>,street=,street2=,city=,province=,postalCode=,country=],primaryPhone=,altPhone=,optInTypes=[],decisionMaker=false,notes=],influenceFunctions=[com.contentconnections.revman.course.InfluenceFunction@1829770[id=2,name=Decision Influencer,description=Holds sway over those making the decision,points=4], com.contentconnections.revman.course.InfluenceFunction@a4461e[id=4,name=Committee Member,description=,points=3]]]
2005-10-27 10:49:09,787 94996 DEBUG [http-8080-Processor18] org.hibernate.event.def.DefaultDeleteEventListener (DefaultDeleteEventListener.java:90) - deleting a persistent instance
2005-10-27 10:49:09,788 94997 DEBUG [http-8080-Processor18] org.hibernate.event.def.DefaultDeleteEventListener (DefaultDeleteEventListener.java:127) - deleting [com.contentconnections.revman.course.InstructorInfluences#component[courseId,instructorId]{instructorId=3, courseId=4}]
2005-10-27 10:49:09,789 94998 DEBUG [http-8080-Processor18] org.hibernate.impl.SessionImpl (SessionImpl.java:1184) - setting cache mode to: GET
2005-10-27 10:49:09,792 95001 DEBUG [http-8080-Processor18] org.hibernate.impl.SessionImpl (SessionImpl.java:1184) - setting cache mode to: NORMAL
2005-10-27 10:49:09,797 95006 DEBUG [http-8080-Processor18] org.hibernate.impl.SessionImpl (SessionImpl.java:1184) - setting cache mode to: GET
2005-10-27 10:49:09,798 95007 DEBUG [http-8080-Processor18] org.hibernate.impl.SessionImpl (SessionImpl.java:1184) - setting cache mode to: NORMAL
2005-10-27 10:49:09,799 95008 DEBUG [http-8080-Processor18] org.springframework.aop.interceptor.CustomizableTraceInterceptor (CustomizableTraceInterceptor.java:280) - exiting CourseDaoHibernateSpringImpl.remove(InstructorInfluences) - returning void
2005-10-27 10:49:09,800 95009 DEBUG [http-8080-Processor18] org.springframework.aop.interceptor.CustomizableTraceInterceptor (CustomizableTraceInterceptor.java:280) - exiting CourseServiceDefaultImpl.removeInstructor(Course,Contact) - returning void
2005-10-27 10:49:09,800 95009 DEBUG [http-8080-Processor18] org.hibernate.transaction.JDBCTransaction (JDBCTransaction.java:103) - commit
2005-10-27 10:49:09,804 95013 DEBUG [http-8080-Processor18] org.hibernate.impl.SessionImpl (SessionImpl.java:343) - automatically flushing session
2005-10-27 10:49:09,805 95014 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:58) - flushing session
2005-10-27 10:49:09,806 95015 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:111) - processing flush-time cascades
2005-10-27 10:49:09,808 95017 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:153) - dirty checking collections
2005-10-27 10:49:09,809 95018 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:170) - Flushing entities and processing referenced collections
2005-10-27 10:49:09,822 95031 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.Institution.types#1], was: [com.contentconnections.revman.Institution.types#1] (initialized)
2005-10-27 10:49:09,823 95032 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.Institution.personnel#1], was: [com.contentconnections.revman.Institution.personnel#1] (uninitialized)
2005-10-27 10:49:09,824 95033 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.Institution.departments#1], was: [com.contentconnections.revman.Institution.departments#1] (uninitialized)
2005-10-27 10:49:09,825 95034 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.Department.disciplines#1], was: [com.contentconnections.revman.Department.disciplines#1] (uninitialized)
2005-10-27 10:49:09,825 95034 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.Department.personnel#1], was: [com.contentconnections.revman.Department.personnel#1] (uninitialized)
2005-10-27 10:49:09,826 95035 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.course.CourseCommonName.disciplines#1], was: [com.contentconnections.revman.course.CourseCommonName.disciplines#1] (uninitialized)
2005-10-27 10:49:09,827 95036 DEBUG [http-8080-Processor18] org.hibernate.event.def.WrapVisitor (WrapVisitor.java:87) - Wrapped collection in role: com.contentconnections.revman.course.InstructorInfluences.influenceFunctions
2005-10-27 10:49:09,827 95036 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=2, courseId=4}], was: [<unreferenced>] (initialized)
2005-10-27 10:49:09,828 95037 DEBUG [http-8080-Processor18] org.hibernate.event.def.WrapVisitor (WrapVisitor.java:87) - Wrapped collection in role: com.contentconnections.revman.course.InstructorInfluences.influenceFunctions
2005-10-27 10:49:09,829 95038 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=1, courseId=4}], was: [<unreferenced>] (initialized)
2005-10-27 10:49:09,829 95038 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.contact.Contact.optInTypes#3], was: [com.contentconnections.revman.contact.Contact.optInTypes#3] (initialized)
2005-10-27 10:49:09,830 95039 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.contact.Contact.sourceLists#3], was: [com.contentconnections.revman.contact.Contact.sourceLists#3] (uninitialized)
2005-10-27 10:49:09,831 95040 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.contact.Contact.touches#3], was: [com.contentconnections.revman.contact.Contact.touches#3] (uninitialized)
2005-10-27 10:49:09,832 95041 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.contact.Contact.optInTypes#2], was: [com.contentconnections.revman.contact.Contact.optInTypes#2] (initialized)
2005-10-27 10:49:09,836 95045 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.contact.Contact.sourceLists#2], was: [com.contentconnections.revman.contact.Contact.sourceLists#2] (uninitialized)
2005-10-27 10:49:09,837 95046 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.contact.Contact.touches#2], was: [com.contentconnections.revman.contact.Contact.touches#2] (uninitialized)
2005-10-27 10:49:09,838 95047 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.contact.Contact.optInTypes#1], was: [com.contentconnections.revman.contact.Contact.optInTypes#1] (initialized)
2005-10-27 10:49:09,838 95047 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.contact.Contact.sourceLists#1], was: [com.contentconnections.revman.contact.Contact.sourceLists#1] (uninitialized)
2005-10-27 10:49:09,839 95048 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:159) - Collection found: [com.contentconnections.revman.contact.Contact.touches#1], was: [com.contentconnections.revman.contact.Contact.touches#1] (uninitialized)
2005-10-27 10:49:09,840 95049 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:209) - Processing unreferenced collections
2005-10-27 10:49:09,840 95049 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:50) - Collection dereferenced: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=3, courseId=4}]
2005-10-27 10:49:09,841 95050 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:50) - Collection dereferenced: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=2, courseId=4}]
2005-10-27 10:49:09,842 95051 DEBUG [http-8080-Processor18] org.hibernate.engine.Collections (Collections.java:50) - Collection dereferenced: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=1, courseId=4}]
2005-10-27 10:49:09,842 95051 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:223) - Scheduling collection removes/(re)creates/updates
2005-10-27 10:49:09,845 95054 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:85) - Flushed: 0 insertions, 0 updates, 1 deletions to 16 objects
2005-10-27 10:49:09,846 95055 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:91) - Flushed: 2 (re)creations, 0 updates, 3 removals to 20 collections
2005-10-27 10:49:09,847 95056 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:83) - listing entities:
2005-10-27 10:49:09,847 95056 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.course.InfluenceFunction{description=Holds sway over those making the decision, name=Decision Influencer, points=4, id=2}
2005-10-27 10:49:09,848 95057 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.InstitutionType{description=, name=4-year, id=2}
2005-10-27 10:49:09,849 95058 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.contact.Contact{gender=M, altPhone=, sourceLists=<uninitialized>, title=com.contentconnections.revman.contact.ContactTitle#1, notes=, address=component[street,street2,city,province,postalCode,country]{postalCode=, street2=, country=, street=, province=, city=}, discipline=, primaryPhone=, optInTypes=[], salutation=1, id=3, firstName=Q, department=com.contentconnections.revman.Department#1, lastName=A, decisionMaker=false, institution=com.contentconnections.revman.Institution#1, touches=<uninitialized>, email=}
2005-10-27 10:49:09,849 95058 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.course.InstructorInfluences{instructor=com.contentconnections.revman.contact.Contact#1, influenceFunctions=[com.contentconnections.revman.course.InfluenceFunction#2, com.contentconnections.revman.course.InfluenceFunction#4, com.contentconnections.revman.course.InfluenceFunction#3], course=com.contentconnections.revman.course.Course#4, id=component[courseId,instructorId]{instructorId=1, courseId=4}}
2005-10-27 10:49:09,850 95059 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.contact.ContactTitle{title=Department Head, description=, priority=1, id=1}
2005-10-27 10:49:09,850 95059 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.course.CourseCommonName{disciplines=<uninitialized>, description=, name=Linear Algebra, id=1}
2005-10-27 10:49:09,851 95060 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.course.InfluenceFunction{description=, name=Decision Maker, points=4, id=3}
2005-10-27 10:49:09,852 95061 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.course.Course{hotLeadComments=, courseNumber=MAT200, commonName=com.contentconnections.revman.course.CourseCommonName#1, actualTitle=Calc I, institution=com.contentconnections.revman.Institution#1, hotLead=false, annualEnrollment=0, adoptionDecision=3, termsOffered=7, id=4, department=com.contentconnections.revman.Department#1}
2005-10-27 10:49:09,855 95064 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.course.InstructorInfluences{instructor=com.contentconnections.revman.contact.Contact#2, influenceFunctions=[com.contentconnections.revman.course.InfluenceFunction#8], course=com.contentconnections.revman.course.Course#4, id=component[courseId,instructorId]{instructorId=2, courseId=4}}
2005-10-27 10:49:09,856 95065 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.contact.Contact{gender=M, altPhone=, sourceLists=<uninitialized>, title=com.contentconnections.revman.contact.ContactTitle#1, notes=, address=component[street,street2,city,province,postalCode,country]{postalCode=, street2=, country=, street=, province=, city=}, discipline=, primaryPhone=, optInTypes=[], salutation=1, id=2, firstName=M, department=com.contentconnections.revman.Department#2, lastName=B, decisionMaker=false, institution=com.contentconnections.revman.Institution#1, touches=<uninitialized>, email=}
2005-10-27 10:49:09,857 95066 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.Department{disciplines=<uninitialized>, phone=, institution=com.contentconnections.revman.Institution#1, url=, enrollment=0, name=Math, personnel=<uninitialized>, id=1}
2005-10-27 10:49:09,857 95066 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.contact.Contact{gender=M, altPhone=, sourceLists=<uninitialized>, title=com.contentconnections.revman.contact.ContactTitle#1, notes=, address=component[street,street2,city,province,postalCode,country]{postalCode=, street2=, country=, street=, province=, city=}, discipline=, primaryPhone=, optInTypes=[], salutation=1, id=1, firstName=R, department=com.contentconnections.revman.Department#2, lastName=W, decisionMaker=false, institution=com.contentconnections.revman.Institution#1, touches=<uninitialized>, email=}
2005-10-27 10:49:09,858 95067 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.course.InstructorInfluences{instructor=com.contentconnections.revman.contact.Contact#3, influenceFunctions=[com.contentconnections.revman.course.InfluenceFunction#2, com.contentconnections.revman.course.InfluenceFunction#4], course=com.contentconnections.revman.course.Course#4, id=component[courseId,instructorId]{instructorId=3, courseId=4}}
2005-10-27 10:49:09,859 95068 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.course.InfluenceFunction{description=, name=None, points=-1, id=8}
2005-10-27 10:49:09,859 95068 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.Institution{directoryUrl=, phone=, catalogUrl=, types=[com.contentconnections.revman.InstitutionType#2], address=component[street,street2,city,province,postalCode,country]{postalCode=, street2=, country=, street=, province=, city=}, url=, departments=<uninitialized>, enrollment=0, name=Arizona State University, personnel=<uninitialized>, id=1}
2005-10-27 10:49:09,860 95069 DEBUG [http-8080-Processor18] org.hibernate.pretty.Printer (Printer.java:90) - com.contentconnections.revman.course.InfluenceFunction{description=, name=Committee Member, points=3, id=4}
2005-10-27 10:49:09,861 95070 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:289) - executing flush
2005-10-27 10:49:09,861 95070 DEBUG [http-8080-Processor18] org.hibernate.persister.collection.AbstractCollectionPersister (AbstractCollectionPersister.java:939) - Deleting collection: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=3, courseId=4}]
2005-10-27 10:49:09,862 95071 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:309) - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2005-10-27 10:49:09,862 95071 DEBUG [http-8080-Processor18] org.hibernate.SQL (AbstractBatcher.java:344) - delete from revman_course_instructor_influence_functions where courseId=? and instructorId=?
Hibernate: delete from revman_course_instructor_influence_functions where courseId=? and instructorId=?
2005-10-27 10:49:09,863 95072 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:413) - preparing statement
2005-10-27 10:49:09,864 95073 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '4' to parameter: 1
2005-10-27 10:49:09,865 95074 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '3' to parameter: 2
2005-10-27 10:49:09,866 95075 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (BatchingBatcher.java:28) - Adding to batch
2005-10-27 10:49:09,868 95077 DEBUG [http-8080-Processor18] org.hibernate.persister.collection.AbstractCollectionPersister (AbstractCollectionPersister.java:969) - done deleting collection
2005-10-27 10:49:09,868 95077 DEBUG [http-8080-Processor18] org.hibernate.persister.collection.AbstractCollectionPersister (AbstractCollectionPersister.java:939) - Deleting collection: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=2, courseId=4}]
2005-10-27 10:49:09,869 95078 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:173) - reusing prepared statement
2005-10-27 10:49:09,869 95078 DEBUG [http-8080-Processor18] org.hibernate.SQL (AbstractBatcher.java:344) - delete from revman_course_instructor_influence_functions where courseId=? and instructorId=?
Hibernate: delete from revman_course_instructor_influence_functions where courseId=? and instructorId=?
2005-10-27 10:49:09,870 95079 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '4' to parameter: 1
2005-10-27 10:49:09,874 95083 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '2' to parameter: 2
2005-10-27 10:49:09,875 95084 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (BatchingBatcher.java:28) - Adding to batch
2005-10-27 10:49:09,875 95084 DEBUG [http-8080-Processor18] org.hibernate.persister.collection.AbstractCollectionPersister (AbstractCollectionPersister.java:969) - done deleting collection
2005-10-27 10:49:09,876 95085 DEBUG [http-8080-Processor18] org.hibernate.persister.collection.AbstractCollectionPersister (AbstractCollectionPersister.java:939) - Deleting collection: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=1, courseId=4}]
2005-10-27 10:49:09,876 95085 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:173) - reusing prepared statement
2005-10-27 10:49:09,877 95086 DEBUG [http-8080-Processor18] org.hibernate.SQL (AbstractBatcher.java:344) - delete from revman_course_instructor_influence_functions where courseId=? and instructorId=?
Hibernate: delete from revman_course_instructor_influence_functions where courseId=? and instructorId=?
2005-10-27 10:49:09,878 95087 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '4' to parameter: 1
2005-10-27 10:49:09,878 95087 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '1' to parameter: 2
2005-10-27 10:49:09,879 95088 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (BatchingBatcher.java:28) - Adding to batch
2005-10-27 10:49:09,879 95088 DEBUG [http-8080-Processor18] org.hibernate.persister.collection.AbstractCollectionPersister (AbstractCollectionPersister.java:969) - done deleting collection
2005-10-27 10:49:09,880 95089 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (BatchingBatcher.java:55) - Executing batch size: 3
2005-10-27 10:49:09,882 95091 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:317) - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2005-10-27 10:49:09,882 95091 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:459) - closing statement
2005-10-27 10:49:09,883 95092 DEBUG [http-8080-Processor18] org.hibernate.persister.collection.AbstractCollectionPersister (AbstractCollectionPersister.java:991) - Inserting collection: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=2, courseId=4}]
2005-10-27 10:49:09,883 95092 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:309) - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2005-10-27 10:49:09,884 95093 DEBUG [http-8080-Processor18] org.hibernate.SQL (AbstractBatcher.java:344) - insert into revman_course_instructor_influence_functions (courseId, instructorId, influenceFunctionId) values (?, ?, ?)
Hibernate: insert into revman_course_instructor_influence_functions (courseId, instructorId, influenceFunctionId) values (?, ?, ?)
2005-10-27 10:49:09,885 95094 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:413) - preparing statement
2005-10-27 10:49:09,885 95094 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '4' to parameter: 1
2005-10-27 10:49:09,886 95095 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '2' to parameter: 2
2005-10-27 10:49:09,887 95096 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '8' to parameter: 3
2005-10-27 10:49:09,887 95096 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (BatchingBatcher.java:28) - Adding to batch
2005-10-27 10:49:09,888 95097 DEBUG [http-8080-Processor18] org.hibernate.persister.collection.AbstractCollectionPersister (AbstractCollectionPersister.java:1037) - done inserting collection: 1 rows inserted
2005-10-27 10:49:09,892 95101 DEBUG [http-8080-Processor18] org.hibernate.persister.collection.AbstractCollectionPersister (AbstractCollectionPersister.java:991) - Inserting collection: [com.contentconnections.revman.course.InstructorInfluences.influenceFunctions#component[courseId,instructorId]{instructorId=1, courseId=4}]
2005-10-27 10:49:09,893 95102 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:173) - reusing prepared statement
2005-10-27 10:49:09,893 95102 DEBUG [http-8080-Processor18] org.hibernate.SQL (AbstractBatcher.java:344) - insert into revman_course_instructor_influence_functions (courseId, instructorId, influenceFunctionId) values (?, ?, ?)
Hibernate: insert into revman_course_instructor_influence_functions (courseId, instructorId, influenceFunctionId) values (?, ?, ?)
2005-10-27 10:49:09,894 95103 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '4' to parameter: 1
2005-10-27 10:49:09,895 95104 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '1' to parameter: 2
2005-10-27 10:49:09,895 95104 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '2' to parameter: 3
2005-10-27 10:49:09,896 95105 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (BatchingBatcher.java:28) - Adding to batch
2005-10-27 10:49:09,896 95105 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:173) - reusing prepared statement
2005-10-27 10:49:09,897 95106 DEBUG [http-8080-Processor18] org.hibernate.SQL (AbstractBatcher.java:344) - insert into revman_course_instructor_influence_functions (courseId, instructorId, influenceFunctionId) values (?, ?, ?)
Hibernate: insert into revman_course_instructor_influence_functions (courseId, instructorId, influenceFunctionId) values (?, ?, ?)
2005-10-27 10:49:09,898 95107 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '4' to parameter: 1
2005-10-27 10:49:09,898 95107 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '1' to parameter: 2
2005-10-27 10:49:09,899 95108 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '4' to parameter: 3
2005-10-27 10:49:09,900 95109 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (BatchingBatcher.java:28) - Adding to batch
2005-10-27 10:49:09,900 95109 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:173) - reusing prepared statement
2005-10-27 10:49:09,901 95110 DEBUG [http-8080-Processor18] org.hibernate.SQL (AbstractBatcher.java:344) - insert into revman_course_instructor_influence_functions (courseId, instructorId, influenceFunctionId) values (?, ?, ?)
Hibernate: insert into revman_course_instructor_influence_functions (courseId, instructorId, influenceFunctionId) values (?, ?, ?)
2005-10-27 10:49:09,902 95111 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '4' to parameter: 1
2005-10-27 10:49:09,902 95111 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '1' to parameter: 2
2005-10-27 10:49:09,903 95112 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '3' to parameter: 3
2005-10-27 10:49:09,903 95112 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (BatchingBatcher.java:28) - Adding to batch
2005-10-27 10:49:09,904 95113 DEBUG [http-8080-Processor18] org.hibernate.persister.collection.AbstractCollectionPersister (AbstractCollectionPersister.java:1037) - done inserting collection: 3 rows inserted
2005-10-27 10:49:09,905 95114 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (BatchingBatcher.java:55) - Executing batch size: 4
2005-10-27 10:49:09,909 95118 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:317) - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2005-10-27 10:49:09,910 95119 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:459) - closing statement
2005-10-27 10:49:09,911 95120 DEBUG [http-8080-Processor18] org.hibernate.persister.entity.AbstractEntityPersister (AbstractEntityPersister.java:2232) - Deleting entity: [com.contentconnections.revman.course.InstructorInfluences#component[courseId,instructorId]{instructorId=3, courseId=4}]
2005-10-27 10:49:09,911 95120 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:309) - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2005-10-27 10:49:09,912 95121 DEBUG [http-8080-Processor18] org.hibernate.SQL (AbstractBatcher.java:344) - delete from revman_course_instructors where courseId=? and instructorId=?
Hibernate: delete from revman_course_instructors where courseId=? and instructorId=?
2005-10-27 10:49:09,913 95122 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:413) - preparing statement
2005-10-27 10:49:09,913 95122 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '4' to parameter: 1
2005-10-27 10:49:09,914 95123 DEBUG [http-8080-Processor18] org.hibernate.type.LongType (NullableType.java:60) - binding '3' to parameter: 2
2005-10-27 10:49:09,915 95124 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (BatchingBatcher.java:28) - Adding to batch
2005-10-27 10:49:09,915 95124 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (BatchingBatcher.java:55) - Executing batch size: 1
2005-10-27 10:49:09,916 95125 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:317) - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2005-10-27 10:49:09,917 95126 DEBUG [http-8080-Processor18] org.hibernate.jdbc.AbstractBatcher (AbstractBatcher.java:459) - closing statement
2005-10-27 10:49:09,923 95132 DEBUG [http-8080-Processor18] org.hibernate.event.def.AbstractFlushingEventListener (AbstractFlushingEventListener.java:316) - post flush
2005-10-27 10:49:09,924 95133 DEBUG [http-8080-Processor18] org.hibernate.jdbc.JDBCContext (JDBCContext.java:178) - before transaction completion
2005-10-27 10:49:09,925 95134 DEBUG [http-8080-Processor18] org.hibernate.impl.SessionImpl (SessionImpl.java:392) - before transaction completion
2005-10-27 10:49:09,926 95135 DEBUG [http-8080-Processor18] org.hibernate.transaction.JDBCTransaction (JDBCTransaction.java:193) - re-enabling autocommit
2005-10-27 10:49:09,926 95135 DEBUG [http-8080-Processor18] org.hibernate.transaction.JDBCTransaction (JDBCTransaction.java:116) - committed JDBC Connection
2005-10-27 10:49:09,927 95136 DEBUG [http-8080-Processor18] org.hibernate.jdbc.JDBCContext (JDBCContext.java:192) - after transaction completion
2005-10-27 10:49:09,927 95136 DEBUG [http-8080-Processor18] org.hibernate.impl.SessionImpl (SessionImpl.java:423) - after transaction completion
2005-10-27 10:49:09,928 95137 DEBUG [http-8080-Processor18] org.hibernate.impl.SessionImpl (SessionImpl.java:1169) - setting flush mode to: NEVER
2005-10-27 10:49:09,931 95140 DEBUG [http-8080-Processor18] com.contentconnections.util.jsf.LogPhaseListener (LogPhaseListener.java:17) - afterPhase () - INVOKE_APPLICATION(5)
2005-10-27 10:49:09,931 95140 DEBUG [http-8080-Processor18] com.contentconnections.util.jsf.LogPhaseListener (LogPhaseListener.java:21) - beforePhase () - RENDER_RESPONSE(6)
2005-10-27 10:49:09,959 95168 DEBUG [http-8080-Processor18] org.hibernate.transaction.JDBCTransaction (JDBCTransaction.java:54) - begin
2005-10-27 10:49:09,960 95169 DEBUG [http-8080-Processor18] org.hibernate.transaction.JDBCTransaction (JDBCTransaction.java:59) - current autocommit status: true
2005-10-27 10:49:09,961 95170 DEBUG [http-8080-Processor18] org.hibernate.transaction.JDBCTransaction (JDBCTransaction.java:62) - disabling autocommit
2005-10-27 10:49:09,962 95171 DEBUG [http-8080-Processor18] org.hibernate.jdbc.JDBCContext (JDBCContext.java:187) - before transaction completion