uPortal IRC Logs-2011-02-14

Owned by Apereo Infrastructure
Last updated: Feb 14, 2011Version comment
8 min read

[11:11:04 CST(-0600)] <athena> hey EricDalquist
[11:11:18 CST(-0600)] <athena> i seem to be unable to get uportal up and running this morning
[11:11:36 CST(-0600)] <EricDalquist> ok
[11:11:38 CST(-0600)] <athena> dropped my database, recreated it, and did both an ant clean initdb and an ant clean deploy-ear
[11:11:41 CST(-0600)] <athena> any suggestions?
[11:11:43 CST(-0600)] <EricDalquist> what is going on?
[11:11:45 CST(-0600)] <EricDalquist> errors?
[11:12:35 CST(-0600)] <athena> http://uportal.pastebin.com/3dR69EPM
[11:12:50 CST(-0600)] <athena> NPE in RDBMDistributedLayoutStore
[11:13:52 CST(-0600)] <athena> database appears to have appropriate content in it, at a first glance
[11:15:37 CST(-0600)] <EricDalquist> can you try it against hsql and see if it works?
[11:15:42 CST(-0600)] <athena> sure (smile)
[11:23:22 CST(-0600)] <athena> ok, yes, hsql works
[11:23:31 CST(-0600)] <EricDalquist> no errors from initdb?
[11:23:35 CST(-0600)] <athena> you know, i bet i forgot to grant my test user privs on the db when i recreated it
[11:23:35 CST(-0600)] <EricDalquist> against postgres?
[11:23:39 CST(-0600)] <athena> let me try this all again
[11:23:41 CST(-0600)] <EricDalquist> ok (smile)
[11:31:55 CST(-0600)] <athena> ok, that appears not to have fixed it
[11:31:59 CST(-0600)] <EricDalquist> yay
[11:31:59 CST(-0600)] <athena> so hsql is working ok
[11:32:03 CST(-0600)] <athena> psql not so much
[11:32:06 CST(-0600)] <EricDalquist> hrm
[11:32:19 CST(-0600)] <EricDalquist> so initdb finishes with no errors at all?
[11:32:23 CST(-0600)] <athena> yep
[11:32:39 CST(-0600)] <EricDalquist> the changes shouldn't have touched those layout tables at all either
[11:32:49 CST(-0600)] <EricDalquist> only JPA managed tables
[11:33:07 CST(-0600)] <EricDalquist> looking in the DB is all the data you expect to see there?
[11:33:09 CST(-0600)] <athena> hm, interesting
[11:33:11 CST(-0600)] <athena> yeah
[11:33:15 CST(-0600)] <athena> seems like it
[11:33:35 CST(-0600)] <athena> there's stuff in users, profiles, layouts, layout_struct
[11:34:47 CST(-0600)] <EricDalquist> same error this time too?
[11:34:53 CST(-0600)] <EricDalquist> and no other exceptions in the portal log?
[11:35:31 CST(-0600)] <athena> let me check
[11:36:03 CST(-0600)] <athena> oh interesting
[11:36:16 CST(-0600)] <athena> good call (smile)
[11:36:30 CST(-0600)] <athena> got down to Caused by: org.postgresql.util.PSQLException: Bad value for type long : "
[11:36:40 CST(-0600)] <athena> and then it prints out the value of one of the content portlet HTML sections
[11:36:51 CST(-0600)] <athena> which seems like something that would indeed be a bad value for a long
[11:37:25 CST(-0600)] <EricDalquist> well LONG is not a number
[11:37:30 CST(-0600)] <EricDalquist> LONG is a long text field
[11:37:36 CST(-0600)] <EricDalquist> this is what I was worried about
[11:37:49 CST(-0600)] <EricDalquist> Hibernate changed some of their text/clob handling
[11:37:51 CST(-0600)] <athena> ohhh
[11:37:53 CST(-0600)] <athena> gotcha
[11:37:54 CST(-0600)] <athena> yeah
[11:37:58 CST(-0600)] <EricDalquist> in a DB numbers are NUMBER
[11:38:03 CST(-0600)] <athena> lets see, that's probably one of the pref tables
[11:38:09 CST(-0600)] <EricDalquist> probably both
[11:38:19 CST(-0600)] <EricDalquist> can you go see what type the pref name and value columns are declared as?
[11:38:34 CST(-0600)] <athena> portlet_pref_id | bigint | not null
[11:38:34 CST(-0600)] <athena> value | text |
[11:38:34 CST(-0600)] <athena> value_order | integer | not null
[11:38:41 CST(-0600)] <athena> value as text seems right?
[11:39:43 CST(-0600)] <EricDalquist> huh yeah
[11:39:47 CST(-0600)] <EricDalquist> that sseems right
[11:39:57 CST(-0600)] <EricDalquist> is there a stack trace for that error message?
[11:40:30 CST(-0600)] <athena> hang on
[11:41:31 CST(-0600)] <athena> here's another sample: http://uportal.pastebin.com/g2MTqyZ4
[11:41:55 CST(-0600)] <athena> oops, here: http://uportal.pastebin.com/djvAHpFs
[11:43:31 CST(-0600)] <athena> this thread seems relevant: http://groups.google.com/group/ebean/browse_thread/thread/b9c09e6522af453b
[11:43:47 CST(-0600)] <athena> links to another thread here: http://archives.postgresql.org/pgsql-jdbc/2010-02/msg00000.php
[11:44:03 CST(-0600)] <EricDalquist> so I'm wondering if it has to do with our custom type
[11:44:17 CST(-0600)] <EricDalquist> I'll have something for you to try in just a second
[11:44:46 CST(-0600)] <athena> sure
[11:44:55 CST(-0600)] <athena> least we're finding this stuff early (smile)
[11:44:55 CST(-0600)] <EricDalquist> so we have a custom UserType that does quoting of certain strings
[11:45:04 CST(-0600)] <EricDalquist> since in most DBs null == ""
[11:45:07 CST(-0600)] <athena> ah
[11:45:12 CST(-0600)] <EricDalquist> which to our java code isn't so much true
[11:45:24 CST(-0600)] <EricDalquist> so the user type adds quotes around the values stored
[11:45:29 CST(-0600)] <EricDalquist> so we can tell the difference
[11:45:47 CST(-0600)] <athena> right
[11:46:07 CST(-0600)] <EricDalquist> but with the change in Lob handling the new user type was much more complex to figure out
[11:46:14 CST(-0600)] <EricDalquist> and seems to be more DB specific
[11:46:22 CST(-0600)] <athena> gotcha
[11:47:15 CST(-0600)] <EricDalquist> ok can you go into PortletPreferenceImpl and replace both places where "@Type(type = "nullSafeClob")" is with "@Lob"
[11:47:24 CST(-0600)] <EricDalquist> you'll need to do a "ant clean initdb deploy-war"
[11:47:26 CST(-0600)] <EricDalquist> and then test
[11:47:32 CST(-0600)] <EricDalquist> that switches to the default hibernate Lob handling
[11:47:39 CST(-0600)] <EricDalquist> which I know works against hsql and oracle
[11:47:44 CST(-0600)] <EricDalquist> and the user type works against both of those
[11:47:55 CST(-0600)] <EricDalquist> but it may be causing the problems for postgress
[11:47:58 CST(-0600)] <athena> ok
[11:48:14 CST(-0600)] <athena> from that thread it sounds like there's some potential weirdness w/ lobs in psql
[11:55:38 CST(-0600)] <athena> doesn't seem to have helped, unfortunately
[11:55:49 CST(-0600)] <EricDalquist> uhg
[11:55:53 CST(-0600)] <EricDalquist> can you post the new stack trace?
[11:55:53 CST(-0600)] <athena> yeah
[11:55:57 CST(-0600)] <athena> same thing
[11:56:12 CST(-0600)] <athena> or actually no
[11:56:22 CST(-0600)] <athena> Caused by: org.postgresql.util.PSQLException: Large Objects may not be used in auto-commit mode.
[11:56:37 CST(-0600)] <athena> so perhaps that is progress
[11:56:38 CST(-0600)] <EricDalquist> oh ... damn I bet it has to be read from within a tx
[11:56:41 CST(-0600)] <athena> yeah
[11:56:42 CST(-0600)] <athena> probably
[11:56:47 CST(-0600)] <EricDalquist> can you post the new stack?
[11:56:52 CST(-0600)] <athena> yeah
[11:57:16 CST(-0600)] <athena> http://uportal.pastebin.com/afUYhuZ3
[11:59:05 CST(-0600)] <EricDalquist> can you include the whole thing?
[11:59:12 CST(-0600)] <EricDalquist> I need to see the path through the DAOs
[11:59:18 CST(-0600)] <athena> ah ok
[11:59:46 CST(-0600)] <athena> hang on - have to get that in a bunch of pieces
[11:59:53 CST(-0600)] <EricDalquist> oh wait ... I think I might know
[12:00:21 CST(-0600)] <EricDalquist> go into hibernate.cfg.xml and delete the line "<property name="hibernate.jdbc.use_streams_for_binary">true</property>"
[12:00:29 CST(-0600)] <EricDalquist> then try a deploy-war and see what happends
[12:00:50 CST(-0600)] <athena> think this should be all of it: http://uportal.pastebin.com/VuhkChRN
[12:00:53 CST(-0600)] <athena> cool i'll try that
[12:10:45 CST(-0600)] <athena> hmm, still getting stack traces
[12:11:04 CST(-0600)] <EricDalquist> ok
[12:11:11 CST(-0600)] <EricDalquist> sorry for the trial and error approach
[12:11:16 CST(-0600)] <EricDalquist> same error about auto-commit?
[12:11:18 CST(-0600)] <athena> s'ok
[12:11:19 CST(-0600)] <athena> yeah
[12:12:01 CST(-0600)] <EricDalquist> next thing ... on "JpaPortletDefinitionDao.getPortletDefinition" add @Transactional(readOnly = true)
[12:13:33 CST(-0600)] <athena> ok
[12:19:20 CST(-0600)] <athena> hurray!
[12:19:36 CST(-0600)] <athena> portal's up now at least
[12:19:57 CST(-0600)] <EricDalquist> ok ... that's good though I worry a little about performance
[12:20:14 CST(-0600)] <athena> because now all this read-only stuff is transactional?
[12:20:18 CST(-0600)] <EricDalquist> lfuller: what is your take on having readOnly transaction annotations on all the portlet definition and entity DAO methods?
[12:20:30 CST(-0600)] <EricDalquist> right, I don't know how much extra overhead that will incure
[12:20:44 CST(-0600)] <EricDalquist> so to really fix this you need to go into both the definition and entity DAOs
[12:20:47 CST(-0600)] <athena> is there any way to get around it? do we need to use lobs?
[12:21:03 CST(-0600)] <EricDalquist> and make sure ALL of the interface defined methods have @Transactional
[12:21:19 CST(-0600)] <EricDalquist> with the non-changing ones getting readonly
[12:21:24 CST(-0600)] <EricDalquist> we could switch it to a varchar
[12:21:34 CST(-0600)] <EricDalquist> and just limit preference names and values at 4k characeters
[12:21:38 CST(-0600)] <EricDalquist> less if you use UTF8
[12:21:48 CST(-0600)] <EricDalquist> for example UTF8 in oracle is 4 bytes/char
[12:22:01 CST(-0600)] <EricDalquist> and a varchar(4000) is a 4000 byte character field
[12:22:19 CST(-0600)] <lfuller> why would we want read only there?
[12:22:20 CST(-0600)] <EricDalquist> so you actually are limited to 1000 characters if you are working in a UTF-8 oracle db
[12:22:35 CST(-0600)] <EricDalquist> lfuller: the problem is postgres requires a TX to read CLOBs
[12:22:47 CST(-0600)] <lfuller> oh...
[12:23:03 CST(-0600)] <EricDalquist> so all of our get methods would require @Transactional
[12:23:17 CST(-0600)] <EricDalquist> and adding readOnly might help on some DBs since we can tell the DB up front we're just reading and not writing
[12:23:32 CST(-0600)] <EricDalquist> but it still could cause additional contention
[12:23:35 CST(-0600)] <EricDalquist> I believe
[12:23:48 CST(-0600)] <lfuller> so you want to put it on only the gets.. .and leave the others as is?
[12:23:54 CST(-0600)] <EricDalquist> right
[12:24:12 CST(-0600)] <EricDalquist> all create/update/delete methods are already marked @Transactional
[12:24:27 CST(-0600)] <EricDalquist> this would be adding @Transactional(readOnly=true) to all the get methods
[12:24:33 CST(-0600)] <lfuller> should be fine... using the old school way of defining things in hibernate native would always set read only on the gets.
[12:24:41 CST(-0600)] <EricDalquist> ah ok
[12:24:57 CST(-0600)] <EricDalquist> well athena do you have a little bit of extra time to add those annotations?
[12:24:58 CST(-0600)] <lfuller> have not done that with JPA... so there could be some pain
[12:25:13 CST(-0600)] <EricDalquist> also canyou switch back to the usertype in the portlet preference object and then see if it all still works?
[12:25:56 CST(-0600)] <EricDalquist> reading up it appears that we're having this problem now because with the old TEXT definition hibernate would use getString() to read the data
[12:26:14 CST(-0600)] <EricDalquist> and it worked because no one using postgres had stored more than 4k bytes of data in a field
[12:26:30 CST(-0600)] <EricDalquist> if you go past that with a TEXT type it spans into additional db records
[12:26:35 CST(-0600)] <EricDalquist> which is why the TX is required
[12:26:37 CST(-0600)] <EricDalquist> :/
[12:28:45 CST(-0600)] <EricDalquist> http://opensource.atlassian.com/projects/hibernate/browse/HHH-4617
[12:30:12 CST(-0600)] <EricDalquist> though that says it was fixed in 3.6.1 which is what we're using ...
[12:30:15 CST(-0600)] <EricDalquist> grr
[12:34:31 CST(-0600)] <athena> EricDalquist: on a call w/ fluid, back shortly
[12:34:37 CST(-0600)] <EricDalquist> ok
[12:35:04 CST(-0600)] <athena> looking at their new builder - should make it easier for us to build new fluid releases (smile)
[12:35:37 CST(-0600)] <athena> but yes, can fix the annotations after this
[13:25:21 CST(-0600)] <athena> ok EricDalquist
[13:25:37 CST(-0600)] <athena> looks like i can revert hibernate.cfg.xml, but not set it back to the custom type
[13:25:45 CST(-0600)] <athena> when i do that i go back to the original error
[13:25:55 CST(-0600)] <athena> working now with that changed to @Lob + the transactional changes
[13:29:42 CST(-0600)] <EricDalquist> ok
[13:29:53 CST(-0600)] <EricDalquist> I think my usertype needs to be a little smarter then
[13:31:40 CST(-0600)] <EricDalquist> brb
[13:36:00 CST(-0600)] <athena> sure
[14:19:58 CST(-0600)] <EricDalquist> athena: do you have some time to help me try out a few other ideas?
[14:21:04 CST(-0600)] <athena> yes
[14:21:19 CST(-0600)] <athena> by the way, what's the timeline on 3.2.5?
[14:21:41 CST(-0600)] <EricDalquist> Could you go back into PortletPreferenceImpl and replace @Lob with @Type(type="text") and then comment out the readonly transactional annotations in the daos?
[14:21:46 CST(-0600)] <EricDalquist> you'd have to do a new initdb
[14:21:53 CST(-0600)] <athena> yep!
[14:22:00 CST(-0600)] <EricDalquist> not sure, I keep trying to work on it and keep getting pulled off
[14:22:04 CST(-0600)] <athena> gotcha
[14:22:08 CST(-0600)] <EricDalquist> I have all day tomorrow blocked off for it
[14:22:11 CST(-0600)] <athena> (smile)
[14:22:12 CST(-0600)] <EricDalquist> so we'll see how that goes
[14:23:25 CST(-0600)] <athena> i hear that
[14:33:01 CST(-0600)] <EricDalquist> ok yeah I'm thinking that change will fix it for you ...
[14:33:04 CST(-0600)] <athena> ok, that seems to have worked
[14:33:05 CST(-0600)] <athena> (smile)
[14:33:38 CST(-0600)] <EricDalquist> ok I have a little testing here but I should have a commit shortly that should have it all straightened out
[14:33:51 CST(-0600)] <athena> awesome (smile)
[14:33:52 CST(-0600)] <athena> thanks so much!
[14:34:01 CST(-0600)] <EricDalquist> thanks for the testing
[14:34:07 CST(-0600)] <athena> no problem
[14:34:11 CST(-0600)] <EricDalquist> now we just need mysql and mssql testers
[16:34:52 CST(-0600)] <EricDalquist> athena: you still there for me to bug again?
[16:35:08 CST(-0600)] <athena> sort of - on a phone call
[16:35:41 CST(-0600)] <EricDalquist> ok, if you get a chance could you try going into PortletPreferenceImpl and changing the @Type to @Type(type = "materialized_clob")
[16:35:49 CST(-0600)] <EricDalquist> and see if that works after an initdb ...
[16:36:02 CST(-0600)] <EricDalquist> reading more and apparently they really re-worked the clob/lob/text handling
[16:36:14 CST(-0600)] <EricDalquist> and it is quiet the pain to get figured out :/
[16:48:20 CST(-0600)] <EricDalquist> actually athena I just committed a change to switch to materialized_clob types. If you replace your local mods with what is in SVN and test that it would be much appreciated
[16:48:38 CST(-0600)] <EricDalquist> I'm heading home soon but I'll try to check with you later on if they worked or not