This is a really strange problem that has me stumped. It only occurs on servers I have in a data center that are virtualized. The problem does not occur locally on my SuSE 10.1 laptop, postgres 8.1.4.
OFBiz 4.0 (also tried using old version of trunk, doesn't seem to be related to a version) Debian 3.1 running in a vserver Java 1.5_06 Postgres 8.0.2 When trying to Complete a shipment, either using the Quick option or explicitly going to pack and then ship, the application just hangs. eCommerce still responds, both secure and not, and I can get a login screen for the backend apps. But when I try to login it hangs too. I've tried increasing the db connection pool. Even tried deploying the app on another server while leaving the unresponsive one running. I could not login from the new deployment until I stopped the hung one on the other machine. This suggests a database issue, but eCommerce still works. It consistently occurs when completing a shipment. I get no information in the log. Below is the output from the start of the request until the console goes dark. 236:INFO ] [Processing Request]: CompletePack sessionId=2354C8175F70C7B3143BB146989D8928.jvm1 2007-07-06 11:07:42,445 (http-0.0.0.0-443-Processor4) [ PackingSession.java:679:INFO ] Creating new shipment with context: [originFacilityId=10000, primaryShipGroupSeqId=00001, primaryOrderId=W600005, shipmentTypeId=OUTGOING_SHIPMENT, statusId=SHIPMENT_INPUT, handlingInstructions=null, picklistBinId=null, additionalShippingCharge=null, userLogin=[GenericEntity:UserLogin][createdStamp,2007-04-17 15:55:11.807(java.sql.Timestamp)][createdTxStamp,2007-04-17 15:55:11.535(java.sql.Timestamp)][currentPassword,47ca69ebb4bdc9ae0adec130880165d2cc05db1a(java.lang.String)][disabledDateTime,null()][enabled,Y(java.lang.String)][hasLoggedOut,N(java.lang.String)][isSystem,null()][lastCurrencyUom,null()][lastLocale,null()][lastUpdatedStamp,2007-07-06 10:20:14.703(java.sql.Timestamp)][lastUpdatedTxStamp,2007-07-06 10:20:14.703(java.sql.Timestamp)][partyId,admin(java.lang.String)][passwordHint,null()][successiveFailedLogins,0(java.lang.Long)][userLoginId,admin(java.lang.String)]] 2007-07-06 11:07:42,499 (http-0.0.0.0-443-Processor4) [ UtilXml.java:243:DEBUG] XML Read 0.052s: file:/root/runningshoes/ofbiz/applications/product/script/org/ofbiz/shipment/shipment/ShipmentServices.xml 2007-07-06 11:07:42,576 (http-0.0.0.0-443-Processor4) [ SequenceUtil.java:254:INFO ] Got bank of sequenced IDs for [Shipment]; curSeqId=10160, maxSeqId=10170, bankSize=10 2007-07-06 11:07:42,577 (http-0.0.0.0-443-Processor4) [XAConnectionFactory.java:119:WARN ] no xares in rms for con [EMAIL PROTECTED] 2007-07-06 11:07:42,713 (http-0.0.0.0-443-Processor4) [ UtilXml.java:243:DEBUG] XML Read 0.074s: file:/root/runningshoes/ofbiz/applications/workeffort/script/org/ofbiz/workeffort/workeffort/WorkEffortSimpleServices.xml 2007-07-06 11:07:42,744 (http-0.0.0.0-443-Processor4) [ SequenceUtil.java:254:INFO ] Got bank of sequenced IDs for [WorkEffort]; curSeqId=10170, maxSeqId=10180, bankSize=10 2007-07-06 11:07:42,781 (http-0.0.0.0-443-Processor4) [ EntityEcaRule.java:111:INFO ] Running Entity ECA Service: indexWorkEffortKeywords, triggered by rule on Entity: WorkEffort 2007-07-06 11:07:42,853 (http-0.0.0.0-443-Processor4) [ ServiceDispatcher.java:459:DEBUG] Sync service [entity-default/indexWorkEffortKeywords] finished in [69] milliseconds 2007-07-06 11:07:42,861 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:137:INFO ] Running Service ECA Service: quickAssignPartyToWorkEffort, triggered by rule on Service: createWorkEffort 2007-07-06 11:07:42,875 (http-0.0.0.0-443-Processor4) [ServiceEcaCondition.java:127:WARN ] From Field (communicationEventId) is not found in context for createWorkEffort, defaulting to null. 2007-07-06 11:07:42,876 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][communicationEventId][is-not-empty][null][][true][String][] 2007-07-06 11:07:42,877 (http-0.0.0.0-443-Processor4) [ ServiceDispatcher.java:459:DEBUG] Sync service [facility/createWorkEffort] finished in [243] milliseconds 2007-07-06 11:07:42,893 (http-0.0.0.0-443-Processor4) [ EntityEcaRule.java:111:INFO ] Running Entity ECA Service: indexWorkEffortKeywords, triggered by rule on Entity: WorkEffort 2007-07-06 11:07:42,952 (http-0.0.0.0-443-Processor4) [ ServiceDispatcher.java:459:DEBUG] Sync service [entity-default/indexWorkEffortKeywords] finished in [58] milliseconds 2007-07-06 11:07:42,955 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:137:INFO ] Running Service ECA Service: quickAssignPartyToWorkEffort, triggered by rule on Service: createWorkEffort 2007-07-06 11:07:42,960 (http-0.0.0.0-443-Processor4) [ServiceEcaCondition.java:127:WARN ] From Field (communicationEventId) is not found in context for createWorkEffort, defaulting to null. 2007-07-06 11:07:42,961 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][communicationEventId][is-not-empty][null][][true][String][] 2007-07-06 11:07:42,961 (http-0.0.0.0-443-Processor4) [ ServiceDispatcher.java:459:DEBUG] Sync service [facility/createWorkEffort] finished in [74] milliseconds 2007-07-06 11:07:42,981 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][SHIPMENT_SCHEDULED][true][String][] 2007-07-06 11:07:42,982 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:137:INFO ] Running Service ECA Service: setShipmentSettingsFromFacilities, triggered by rule on Service: createShipment 2007-07-06 11:07:42,995 (http-0.0.0.0-443-Processor4) [ FieldToResult.java:66 :WARN ] Field value not found with name lookedUpValue.destinationFacilityId in Map with name 2007-07-06 11:07:43,006 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][SHIPMENT_PACKED][true][String][] 2007-07-06 11:07:43,007 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][PURCH_SHIP_RECEIVED][true][String][] 2007-07-06 11:07:43,008 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][PURCH_SHIP_SHIPPED][true][String][] 2007-07-06 11:07:43,008 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][PURCH_SHIP_RECEIVED][true][String][] 2007-07-06 11:07:43,009 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][PURCH_SHIP_RECEIVED][true][String][] 2007-07-06 11:07:43,010 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][SHIPMENT_SCHEDULED][true][String][] 2007-07-06 11:07:43,011 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][originFacilityId][not-equals][][oldOriginFacilityId][false][String][] 2007-07-06 11:07:43,011 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][destinationFacilityId][is-not-empty][null][][true][String][] 2007-07-06 11:07:43,012 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][primaryOrderId][not-equals][][oldPrimaryOrderId][false][String][] 2007-07-06 11:07:43,016 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][SHIPMENT_PACKED][true][String][] 2007-07-06 11:07:43,017 (http-0.0.0.0-443-Processor4) [ServiceEcaCondition.java:127:WARN ] From Field (destinationFacilityId) is not found in context for createShipment, defaulting to null. 2007-07-06 11:07:43,018 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][destinationFacilityId][is-not-empty][null][][true][String][] 2007-07-06 11:07:43,018 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:137:INFO ] Running Service ECA Service: setShipmentSettingsFromPrimaryOrder, triggered by rule on Service: createShipment 2007-07-06 11:07:43,083 (http-0.0.0.0-443-Processor4) [ EntityEcaRule.java:111:INFO ] Running Entity ECA Service: setShipmentRouteSegmentFromShipGroup, triggered by rule on Entity: ShipmentRouteSegment 2007-07-06 11:07:43,140 (http-0.0.0.0-443-Processor4) [ FieldToResult.java:66 :WARN ] Field value not found with name lookedUpValue.destinationFacilityId in Map with name 2007-07-06 11:07:43,148 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][SHIPMENT_PACKED][true][String][] 2007-07-06 11:07:43,149 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][PURCH_SHIP_RECEIVED][true][String][] 2007-07-06 11:07:43,150 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][PURCH_SHIP_SHIPPED][true][String][] 2007-07-06 11:07:43,151 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][PURCH_SHIP_RECEIVED][true][String][] 2007-07-06 11:07:43,152 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][PURCH_SHIP_RECEIVED][true][String][] 2007-07-06 11:07:43,152 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][SHIPMENT_SCHEDULED][true][String][] 2007-07-06 11:07:43,153 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][originFacilityId][not-equals][][oldOriginFacilityId][false][String][] 2007-07-06 11:07:43,154 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][destinationFacilityId][is-not-empty][null][][true][String][] 2007-07-06 11:07:43,155 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][primaryOrderId][not-equals][][oldPrimaryOrderId][false][String][] 2007-07-06 11:07:43,155 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][SHIPMENT_PACKED][true][String][] 2007-07-06 11:07:43,156 (http-0.0.0.0-443-Processor4) [ ServiceDispatcher.java:459:DEBUG] Sync service [facility/setShipmentSettingsFromPrimaryOrder] finished in [137] milliseconds 2007-07-06 11:07:43,157 (http-0.0.0.0-443-Processor4) [ ServiceDispatcher.java:459:DEBUG] Sync service [facility/createShipment] finished in [711] milliseconds 2007-07-06 11:07:43,338 (http-0.0.0.0-443-Processor4) [ ServiceDispatcher.java:459:DEBUG] Sync service [facility/createShipmentPackage] finished in [180] milliseconds 2007-07-06 11:07:43,398 (http-0.0.0.0-443-Processor4) [ UtilXml.java:243:DEBUG] XML Read 0.057s: file:/root/runningshoes/ofbiz/applications/product/script/org/ofbiz/shipment/issuance/IssuanceServices.xml 2007-07-06 11:07:43,407 (http-0.0.0.0-443-Processor4) [ Log.java:94 :INFO ] order item ship grp inv res info: [GenericEntity:OrderItemShipGrpInvRes][createdDatetime,2007-07-05 14:04:40.817(java.sql.Timestamp)][createdStamp,2007-07-05 14:04:40.817(java.sql.Timestamp)][createdTxStamp,2007-07-05 14:04:39.272(java.sql.Timestamp)][currentPromisedDate,null()][inventoryItemId,10050(java.lang.String)][lastUpdatedStamp,2007-07-05 14:04:40.817(java.sql.Timestamp)][lastUpdatedTxStamp,2007-07-05 14:04:39.272(java.sql.Timestamp)][oldPickStartDate,null()][orderId,W600005(java.lang.String)][orderItemSeqId,00001(java.lang.String)][promisedDatetime,2007-07-08 14:00:29.021(java.sql.Timestamp)][quantity,2.0(java.lang.Double)][quantityNotAvailable,null()][reserveOrderEnumId,INVRO_FIFO_REC(java.lang.String)][reservedDatetime,2007-07-05 14:00:29.938(java.sql.Timestamp)][shipGroupSeqId,00001(java.lang.String)] 2007-07-06 11:07:43,421 (http-0.0.0.0-443-Processor4) [ Calculate.java:342:INFO ] Field not found with field-name orderShipment.quantity, and map-name using a default of 0 2007-07-06 11:07:43,439 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:137:INFO ] Running Service ECA Service: checkCreateStockRequirementQoh, triggered by rule on Service: createItemIssuance 2007-07-06 11:07:43,477 (http-0.0.0.0-443-Processor4) [ UtilXml.java:243:DEBUG] XML Read 0.036s: file:/root/runningshoes/ofbiz/applications/order/script/org/ofbiz/order/order/OrderServices.xml 2007-07-06 11:07:43,496 (http-0.0.0.0-443-Processor4) [ ServiceDispatcher.java:459:DEBUG] Sync service [facility/checkCreateStockRequirementQoh] finished in [56] milliseconds 2007-07-06 11:07:43,506 (http-0.0.0.0-443-Processor4) [ SequenceUtil.java:254:INFO ] Got bank of sequenced IDs for [ItemIssuance]; curSeqId=10150, maxSeqId=10160, bankSize=10 2007-07-06 11:07:43,552 (http-0.0.0.0-443-Processor4) [ ServiceDispatcher.java:459:DEBUG] Sync service [facility/createItemIssuance] finished in [114] milliseconds 2007-07-06 11:07:43,603 (http-0.0.0.0-443-Processor4) [ SequenceUtil.java:254:INFO ] Got bank of sequenced IDs for [EntitySyncRemove]; curSeqId=11050, maxSeqId=11060, bankSize=10 2007-07-06 11:07:43,692 (http-0.0.0.0-443-Processor4) [ SequenceUtil.java:254:INFO ] Got bank of sequenced IDs for [OrderStatus]; curSeqId=10380, maxSeqId=10390, bankSize=10 2007-07-06 11:07:43,735 (http-0.0.0.0-443-Processor4) [ EntityEcaRule.java:111:INFO ] Running Entity ECA Service: checkCreateOrderRequirement, triggered by rule on Entity: OrderItem 2007-07-06 11:07:43,739 (http-0.0.0.0-443-Processor4) [ PrimaryKeyFinder.java:124:INFO ] Returning null because found incomplete primary key in find: [GenericEntity:Product] 2007-07-06 11:07:43,751 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][ITEM_CANCELLED][true][String][] 2007-07-06 11:07:43,752 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:137:INFO ] Running Service ECA Service: checkOrderItemStatus, triggered by rule on Service: changeOrderItemStatus 2007-07-06 11:07:43,779 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:112:INFO ] Got false for condition: [null][][statusId][equals][null][ORDER_CANCELLED][true][String][] 2007-07-06 11:07:43,780 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:137:INFO ] Running Service ECA Service: resetGrandTotal, triggered by rule on Service: changeOrderStatus 2007-07-06 11:07:43,794 (http-0.0.0.0-443-Processor4) [ GenericEntity.java:386:WARN ] In entity field [OrderHeader.grandTotal] set the value passed in [java.math.BigDecimal] is not compatible with the Java type of the field [Double] 2007-07-06 11:07:43,795 (http-0.0.0.0-443-Processor4) [ GenericEntity.java:386:WARN ] In entity field [OrderHeader.remainingSubTotal] set the value passed in [java.math.BigDecimal] is not compatible with the Java type of the field [Double] 2007-07-06 11:07:43,805 (http-0.0.0.0-443-Processor4) [ ServiceEcaRule.java:137:INFO ] Running Service ECA Service: sendOrderCompleteNotification, triggered by rule on Service: changeOrderStatus 2007-07-06 11:07:43,806 (http-0.0.0.0-443-Processor4) [ ServiceDispatcher.java:480:DEBUG] [[ASync service started...- total:0.0,since last(Begin):0.0]] - 'facility / sendOrderCompleteNotification' 2007-07-06 11:07:43,815 (http-0.0.0.0-443-Processor4) [ SequenceUtil.java:254:INFO ] Got bank of sequenced IDs for [RuntimeData]; curSeqId=10310, maxSeqId=10320, bankSize=10 2007-07-06 11:07:43,860 (http-0.0.0.0-443-Processor4) [ SequenceUtil.java:254:INFO ] Got bank of sequenced IDs for [JobSandbox]; curSeqId=10930, maxSeqId=10940, bankSize=10 -- Vince Clark Global Era The freedom of open source. (303) 493-6723 (303) 455-2409 fax [EMAIL PROTECTED] <mailto:[EMAIL PROTECTED]> www.globalera.com
