Project

General

Profile

Revision 5162

Added by daigle over 11 years ago

Change log levels where appropriate and add class/method name to output.

View differences:

src/edu/ucsb/nceas/metacat/DocumentImpl.java
351 351
            String docIdWithoutRev = DocumentUtil.getDocIdFromAccessionNumber(accnum);
352 352
            int userSpecifyRev = DocumentUtil.getRevisionFromAccessionNumber(accnum);
353 353
            action = checkRevInXMLDocuments(docIdWithoutRev, userSpecifyRev);
354
            logMetacat.warn("after check rev, the action is "+action);
354
            logMetacat.debug("after check rev, the action is " + action);
355 355
            if (action.equals("UPDATE"))
356 356
            {
357 357
                //archive the old entry
......
638 638
        {
639 639
          ForceReplicationHandler forceReplication = new ForceReplicationHandler(
640 640
                accnum, false, notificationServer);
641
          logMetacat.debug("ForceReplicationHandler created: " + forceReplication.toString());
641
          logMetacat.info("ForceReplicationHandler created: " + forceReplication.toString());
642 642
        }
643 643
    }
644 644
    
......
650 650
     private static String checkRevInXMLDocuments(String docid, int userSpecifyRev) throws Exception
651 651
     {
652 652
        String action = null;
653
        logMetacat.warn("The docid without rev is "+docid);
654
        logMetacat.warn("The user specifyRev: " + userSpecifyRev);
653
        logMetacat.debug("The docid without rev is "+docid);
654
        logMetacat.debug("The user specifyRev: " + userSpecifyRev);
655 655
        // Revision for this docid in current database
656 656
        int revInDataBase =DBUtil.getLatestRevisionInDocumentTable(docid);
657
        logMetacat.warn("The rev in data base: " + revInDataBase);
657
        logMetacat.debug("The rev in data base: " + revInDataBase);
658 658
        // String to store the revision
659 659
//        String rev = null;
660 660

  
......
712 712
                   "written because error happend to find it's local revision");
713 713
           throw new Exception (e.getMessage());
714 714
         }
715
         logMetacat.info("rev list in xml_revision table for docid "+ docid + " is "+
715
         logMetacat.debug("rev list in xml_revision table for docid "+ docid + " is "+
716 716
                                 localrev.toString());
717 717
         
718 718
         // if the rev is in the xml_revision, it throws a exception
......
1574 1574
	 */
1575 1575
    public void buildIndex() throws McdbException
1576 1576
    {
1577
    	logMetacat.warn("buildIndex called on docid " + docid);
1577
    	logMetacat.info("buildIndex called on docid " + docid);
1578 1578
    	double start = System.currentTimeMillis()/1000;
1579 1579
        TreeSet<NodeRecord> nodeRecordLists = getNodeRecordList(rootnodeid);
1580 1580
        boolean atRootElement = true;
......
1592 1592

  
1593 1593
//        String doc = docid;
1594 1594
      double afterPutNode = System.currentTimeMillis()/1000;
1595
      logMetacat.info("The time for put node id into map is "+(afterPutNode - start));
1595
      logMetacat.debug("The time for put node id into map is "+(afterPutNode - start));
1596 1596
      double afterDelete = 0;
1597 1597
        // Opening separate db connection for deleting and writing
1598 1598
        // XML Index -- be sure that it is all in one db transaction
......
1678 1678
		}
1679 1679
		double finish = System.currentTimeMillis() / 1000;
1680 1680
		logMetacat.info("The time for inserting is " + (finish - afterDelete));
1681
		logMetacat.warn("BuildIndex complete for docid " + docid);
1681
		logMetacat.info("BuildIndex complete for docid " + docid);
1682 1682

  
1683 1683
		// Adds the docid to the spatial data cache
1684 1684
		try {
1685 1685
			if (PropertyService.getProperty("spatial.runSpatialOption").equals("true")) {
1686 1686
				SpatialHarvester spatialHarvester = new SpatialHarvester();
1687
				logMetacat.info(" --------- Attempting to update the spatial cache for docid "
1687
				logMetacat.debug(" --------- Attempting to update the spatial cache for docid "
1688 1688
								+ docid);
1689 1689
				spatialHarvester.addToUpdateQue(docid);
1690 1690
				spatialHarvester.destroy();
1691
				logMetacat.info(" --------- Finish to update the spatial cache for docid "
1691
				logMetacat.debug(" --------- Finish to update the spatial cache for docid "
1692 1692
								+ docid);
1693 1693
			}
1694 1694
		} catch (PropertyNotFoundException pnfe) {
......
1827 1827
    	double start = System.currentTimeMillis()/1000;
1828 1828
        String familyId = docid;
1829 1829
        String sql = "DELETE FROM xml_index WHERE docid = ?";
1830
        logMetacat.debug(sql);
1831
        logMetacat.debug("SQL is: " + sql);
1830
        logMetacat.debug("DocumentImpl.deleteNodeIndex - SQL is: " + sql);
1832 1831

  
1833 1832
        PreparedStatement pstmt = conn.prepareStatement(sql);
1834 1833

  
......
1839 1838
        pstmt.setString(1, familyId);
1840 1839
        int rows = pstmt.executeUpdate();
1841 1840
        pstmt.close();
1842
        logMetacat.info("Deleted " + rows + " rows from xml_index " +
1841
        logMetacat.debug("DocumentImpl.deleteNodeIndex - Deleted " + rows + " rows from xml_index " +
1843 1842
            "for document " + docid);
1844 1843
        double afterDeleteIndex = System.currentTimeMillis()/1000;
1845
        logMetacat.info("The delete index time is "+(afterDeleteIndex - start));
1844
        logMetacat.debug("DocumentImpl.deleteNodeIndex - The delete index time is "+(afterDeleteIndex - start));
1846 1845
        // Delete all the entries in xml_queryresult
1847 1846
        pstmt = conn.prepareStatement(
1848 1847
                "DELETE FROM xml_queryresult WHERE docid = ?");
......
1850 1849
        rows = pstmt.executeUpdate();
1851 1850
        conn.increaseUsageCount(1);
1852 1851
        pstmt.close();
1853
        logMetacat.info("Deleted " + rows + " rows from xml_queryresult " +
1852
        logMetacat.debug("DocumentImpl.deleteNodeIndex - Deleted " + rows + " rows from xml_queryresult " +
1854 1853
                "for document " + docid);
1855 1854
        double afterDeleteQueryResult = System.currentTimeMillis()/1000;
1856
        logMetacat.info("The delete query result time is "+(afterDeleteQueryResult - afterDeleteIndex ));
1855
        logMetacat.debug("DocumentImpl.deleteNodeIndex - The delete query result time is "+(afterDeleteQueryResult - afterDeleteIndex ));
1857 1856
        // Delete all the entries in xml_path_index
1858 1857
        pstmt = conn.prepareStatement(
1859 1858
                "DELETE FROM xml_path_index WHERE docid = ?");
......
1862 1861
        conn.increaseUsageCount(1);
1863 1862
        pstmt.close();
1864 1863
        double afterDeletePathIndex = System.currentTimeMillis()/1000;
1865
        logMetacat.info("The delete path index time is "+ (afterDeletePathIndex - afterDeleteQueryResult));
1866
        logMetacat.info("Deleted " + rows + " rows from xml_path_index " +
1864
        logMetacat.info("DocumentImpl.deleteNodeIndex - The delete path index time is "+ (afterDeletePathIndex - afterDeleteQueryResult));
1865
        logMetacat.info("DocumentImpl.deleteNodeIndex - Deleted " + rows + " rows from xml_path_index " +
1867 1866
                "for document " + docid);
1868 1867

  
1869 1868
    }
......
1894 1893
        Iterator<PathIndexEntry> it = pathList.values().iterator();
1895 1894
        while (it.hasNext()) {
1896 1895
        	 PathIndexEntry entry = (PathIndexEntry)it.next();
1897
        	 logMetacat.debug("Inserting: " + entry.nodeId +
1896
        	 logMetacat.debug("DocumentImpl.updateNodeIndex - Inserting: " + entry.nodeId +
1898 1897
        			 " (" + entry.parentId + "): " + entry.path);
1899 1898
        	 pstmt.setLong(1, entry.nodeId);
1900 1899
        	 pstmt.setString(2, entry.path);
......
2040 2039
            throw notFound;
2041 2040
        } catch (Exception e) {
2042 2041

  
2043
            logMetacat.error("error in DocumentImpl.getDocumentInfo: "
2044
                    + e.getMessage());
2042
            logMetacat.error("DocumentImpl.getDocumentInfo - general error: " +
2043
                    e.getMessage());
2045 2044
            throw e;
2046 2045
        }
2047 2046

  
......
2095 2094
                    this.docHomeServer = MetacatUtil
2096 2095
                            .getLocalReplicationServerName();
2097 2096
                }
2098
                logMetacat.info("server: " + docHomeServer);
2097
                logMetacat.debug("DocumentImpl.getDocumentInfo - server: " + docHomeServer);
2099 2098

  
2100 2099
            }
2101 2100
            pstmt.close();
......
2122 2121
                pstmt.close();
2123 2122
            }
2124 2123
        } catch (SQLException e) {
2125
            logMetacat.error("error in DocumentImpl.getDocumentInfo: "
2124
            logMetacat.error("DocumentImpl.getDocumentInfo - Error in DocumentImpl.getDocumentInfo: "
2126 2125
                    + e.getMessage());
2127 2126
            e.printStackTrace(System.out);
2128
            throw new McdbException("Error accessing database connection in "
2129
                    + "DocumentImpl.getDocumentInfo: ", e);
2127
            throw new McdbException("DocumentImpl.getDocumentInfo - Error accessing database connection: ", e);
2130 2128
        } finally {
2131 2129
            try {
2132 2130
                pstmt.close();
2133 2131
            } catch (SQLException ee) {
2134
                logMetacat.error(
2135
                        "error in DocumentImple.getDocumentInfo: "
2136
                                + ee.getMessage());
2132
                logMetacat.error("DocumentImpl.getDocumentInfo - General error" + ee.getMessage());
2137 2133
            } finally {
2138 2134
                DBConnectionPool.returnDBConnection(dbconn, serialNumber);
2139 2135
            }
......
2179 2175
            throw notFound;
2180 2176
        } catch (Exception e) {
2181 2177

  
2182
            logMetacat.error("error in DocumentImpl.getNodeRecordList: "
2178
            logMetacat.error("DocumentImpl.getNodeRecordList - General error: "
2183 2179
                    + e.getMessage());
2184 2180
        }
2185 2181
        //System.out.println("in getNodeREcorelist !!!!!!!!!!!3");
......
2210 2206
                nodedata = rs.getString(7);
2211 2207
                try
2212 2208
                {
2213
                	logMetacat.debug("Node data in read process before normalize=== "+nodedata);
2209
                	logMetacat.debug("DocumentImpl.getNodeRecordList - Node data in read process before normalize=== "+nodedata);
2214 2210
                	nodedata = MetacatUtil.normalize(nodedata);
2215
                	logMetacat.debug("Node data in read process after normalize==== "+nodedata);
2211
                	logMetacat.debug("DocumentImpl.getNodeRecordList - Node data in read process after normalize==== "+nodedata);
2216 2212
                } catch (java.lang.StringIndexOutOfBoundsException SIO){
2217
                	logMetacat.warn("StringIndexOutOfBoundsException in normalize() while reading the document");
2213
                	logMetacat.warn("DocumentImpl.getNodeRecordList - StringIndexOutOfBoundsException in normalize() while reading the document");
2218 2214
                }
2219 2215
                nodedatanumerical = rs.getFloat(8);
2220 2216
                
......
2236 2232
            try {
2237 2233
                pstmt.close();
2238 2234
            } catch (SQLException ee) {
2239
                logMetacat.error(
2240
                        "error in DocumentImpl.getNodeRecordList: "
2235
                logMetacat.error("DocumentImpl.getNodeRecordList - General error: "
2241 2236
                                + ee.getMessage());
2242 2237
            } finally {
2243 2238
                DBConnectionPool.returnDBConnection(dbconn, serialNumber);
......
2339 2334
                
2340 2335
            } else if (action.equals("UPDATE")) {
2341 2336
                int thisrev = DBUtil.getLatestRevisionInDocumentTable(docid);
2342
                logMetacat.info("this revsion is: " + thisrev);
2337
                logMetacat.debug("DocumentImpl.writeDocumentToDB - this revsion is: " + thisrev);
2343 2338
                // Save the old document publicaccessentry in a backup table
2344 2339
                String accNumber = docid+PropertyService.getProperty("document.accNumSeparator")+thisrev;
2345 2340
                thisdoc = new DocumentImpl(accNumber, false);
2346 2341
                DocumentImpl.archiveDocAndNodesRevision(connection, docid, user, thisdoc);
2347
                logMetacat.info("after archiveDoc");
2342
                logMetacat.debug("DocumentImpl.writeDocumentToDB - after archiveDoc");
2348 2343
                //if the updated vesion is not greater than current one,
2349 2344
                //throw it into a exception
2350 2345
                if (rev <= thisrev) {
......
2354 2349
                    //set the user specified revision
2355 2350
                    thisrev = rev;
2356 2351
                }
2357
                logMetacat.info("final revsion is: " + thisrev);
2352
                logMetacat.debug("DocumentImpl.writeDocumentToDB - final revsion is: " + thisrev);
2358 2353
                boolean useXMLIndex = (new Boolean(PropertyService
2359 2354
                        .getProperty("database.usexmlindex"))).booleanValue();
2360 2355
                if (useXMLIndex) {
2361
                    logMetacat.info("before delete");
2356
                    logMetacat.debug("DocumentImpl.writeDocumentToDB - before delete");
2362 2357
                    double start = System.currentTimeMillis()/1000;
2363 2358
                    // Delete index for the old version of docid
2364 2359
                    // The new index is inserting on the next calls to DBSAXNode
......
2373 2368
                  
2374 2369
                    pstmt.close();
2375 2370
                    double end = System.currentTimeMillis()/1000;
2376
                    logMetacat.info("Time for deletindex xml_index in UPDATE is "+(end -start));
2371
                    logMetacat.info("DocumentImpl.writeDocumentToDB - Time for deletindex xml_index in UPDATE is "+(end -start));
2377 2372
                }
2378 2373

  
2379 2374
                // Update the new document to reflect the new node tree
......
2550 2545
    	// Get the xml as a string so we can write to file later
2551 2546
    	String xmlString = StringUtil.readerToString(xml);
2552 2547
    	
2553
        logMetacat.info("DocumentImpl.write - conn usage count before writting: "
2548
        logMetacat.debug("DocumentImpl.write - conn usage count before writting: "
2554 2549
                + conn.getUsageCount());
2555 2550
        AccessionNumber ac = new AccessionNumber(accnum, action);
2556 2551
        String docid = ac.getDocid();
2557 2552
        String rev = ac.getRev();
2558
        logMetacat.info("DocumentImpl.write - action: " + action + " servercode: "
2553
        logMetacat.debug("DocumentImpl.write - action: " + action + " servercode: "
2559 2554
                + serverCode + " override: " + override);
2560 2555

  
2561 2556
        if ((serverCode != 1 && action.equals("UPDATE")) && !override) {
......
2598 2593
                     * XMLReader parser = initializeParser(conn, action, docid,
2599 2594
                     * updaterev, validate, user, groups, pub, serverCode, dtd);
2600 2595
                     */
2601
                    logMetacat.debug("initializing parser");
2596
                    logMetacat.debug("DocumentImpl.write - initializing parser");
2602 2597
                    parser = initializeParser(conn, action, docid, xml, updaterev,
2603 2598
                            user, groups, pub, serverCode, dtd, ruleBase,
2604 2599
                            needValidation, false, null, null);// false means it is not a revision doc
2605 2600
                                   //null, null are createdate and updatedate
2606 2601
                                   //null will use current time as create date time
2607 2602
                    conn.setAutoCommit(false);
2608
                    logMetacat.debug("parsing xml");
2603
                    logMetacat.debug("DocumentImpl.write - parsing xml");
2609 2604
                    parser.parse(new InputSource(xml));
2610 2605
                    conn.commit();
2611 2606
                    conn.setAutoCommit(true);
2612 2607
                    
2613 2608
                    //write the file to disk
2614
                    logMetacat.debug("Writing xml to file system");
2609
                    logMetacat.debug("DocumentImpl.write - Writing xml to file system");
2615 2610
                	writeToFileSystem(xmlString, accnum);
2616 2611

  
2617 2612
                    // write to xml_node complete. start the indexing thread.
2618 2613
                    addDocidToIndexingQueue(docid, rev);
2619 2614
               } catch (Exception e) {
2620
            	   logMetacat.error("Problem with parsing: " + e.getMessage());
2615
            	   logMetacat.error("DocumentImpl.write - Problem with parsing: " + e.getMessage());
2621 2616
                    conn.rollback();
2622 2617
                    conn.setAutoCommit(true);
2623 2618
                    //if it is a eml2 document, we need delete online data
......
2804 2799
        String docType = null;
2805 2800
        String docName = null;
2806 2801
        String catalogId = null;
2807
        logMetacat.info("user in replication" + user);
2802
        logMetacat.debug("DocumentImpl.writeReplication - user in replication" + user);
2808 2803
        // Docid without revision
2809 2804
        String docid = DocumentUtil.getDocIdFromAccessionNumber(accnum);
2810
        logMetacat.warn("The docid without rev is " + docid);
2805
        logMetacat.debug("DocumentImpl.writeReplication - The docid without rev is " + docid);
2811 2806
        // Revision specified by user (int)
2812 2807
        int userSpecifyRev = DocumentUtil.getRevisionFromAccessionNumber(accnum);
2813
        logMetacat.warn("The user specifyRev: " + userSpecifyRev);
2808
        logMetacat.debug("DocumentImpl.writeReplication - The user specifyRev: " + userSpecifyRev);
2814 2809
        // Revision for this docid in current database
2815 2810
        int revInDataBase = DBUtil.getLatestRevisionInDocumentTable(docid);
2816
        logMetacat.warn("The rev in data base: " + revInDataBase);
2811
        logMetacat.debug("DocumentImpl.writeReplication - The rev in data base: " + revInDataBase);
2817 2812
        // String to store the revision
2818 2813
        String rev = (new Integer(userSpecifyRev)).toString();
2819 2814

  
......
2839 2834
        // Get server code again
2840 2835
        serverCode = getServerCode(homeServer);
2841 2836

  
2842
        logMetacat.warn("Document " + docid + "." + rev + " " + action
2837
        logMetacat.info("DocumentImpl.writeReplication - Document " + docid + "." + rev + " " + action
2843 2838
                        + " into local" + " metacat with servercode: "
2844 2839
                        + serverCode);
2845 2840

  
......
2878 2873
            catalogId = dbx.getCatalogId();
2879 2874

  
2880 2875
        } catch (Exception e) {
2881
        	logMetacat.error("Problem with parsing: " + e.getMessage());
2876
        	logMetacat.error("DocumentImpl.writeReplication - Problem with parsing: " + e.getMessage());
2882 2877
            conn.rollback();
2883 2878
            conn.setAutoCommit(true);
2884 2879
            if (parser != null) {
......
2921 2916
                // we need to delete the nodes in xml_ndoes.
2922 2917
                deleteXMLNodes(conn, rootId);
2923 2918
            }
2924
            logReplication.error("Failed to " + "create access "
2919
            logReplication.error("DocumentImpl.writeReplication - Failed to " + "create access "
2925 2920
                    + "rule for package: " + accnum + " because "
2926 2921
                    + ee.getMessage());
2927
            logMetacat.error("Failed to  " + "create access "
2922
            logMetacat.error("DocumentImpl.writeReplication - Failed to  " + "create access "
2928 2923
                    + "rule for package: " + accnum + " because "
2929 2924
                    + ee.getMessage());
2930 2925
        }
......
2934 2929
        {
2935 2930
          ForceReplicationHandler forceReplication = new ForceReplicationHandler(
2936 2931
                accnum, action, true, notifyServer);
2937
          logMetacat.debug("ForceReplicationHandler created: " + forceReplication.toString());
2932
          logMetacat.debug("DocumentImpl.writeReplication - ForceReplicationHandler created: " + forceReplication.toString());
2938 2933
        }
2939 2934
        
2940 2935
        // clear cache after inserting or updating a document
......
3005 3000
                dbconn.rollback();
3006 3001
                dbconn.setAutoCommit(true);
3007 3002
            }
3008
            logMetacat.error(
3009
                    "Error in DocumentImple.runRelationAndAccessHandler "
3003
            logMetacat.error("DocumentImpl.runRelationAndAccessHandler - Error in DocumentImple.runRelationAndAccessHandler "
3010 3004
                            + e.getMessage());
3011 3005
            throw e;
3012 3006
        } finally {
......
3031 3025
    private static String getDocTypeFromDBForCurrentDocument(String accnumber)
3032 3026
            throws SQLException
3033 3027
    {
3034
        String docoumentType = null;
3028
        String documentType = null;
3035 3029
        String docid = null;
3036 3030
        PreparedStatement pstate = null;
3037 3031
        ResultSet rs = null;
......
3052 3046
            //handle resultset
3053 3047
            rs = pstate.getResultSet();
3054 3048
            if (rs.next()) {
3055
                docoumentType = rs.getString(1);
3049
                documentType = rs.getString(1);
3056 3050
            }
3057 3051
            rs.close();
3058 3052
            pstate.close();
3059 3053
        }//try
3060 3054
        catch (SQLException e) {
3061
            logMetacat.error("error in DocumentImpl."
3062
                    + "getDocTypeFromDBForCurrentDocument " + e.getMessage());
3055
            logMetacat.error("DocumentImpl.getDocTypeFromDBForCurrentDocument - SQL error: " + 
3056
            		e.getMessage());
3063 3057
            throw e;
3064 3058
        }//catch
3065 3059
        finally {
3066 3060
            pstate.close();
3067 3061
            DBConnectionPool.returnDBConnection(dbConnection, serialNumber);
3068 3062
        }//
3069
        logMetacat.info("The current doctype from db is: "
3070
                + docoumentType);
3071
        return docoumentType;
3063
        logMetacat.debug("DocumentImpl.getDocTypeFromDBForCurrentDocument - The current doctype from db is: "
3064
                + documentType);
3065
        return documentType;
3072 3066
    }
3073 3067

  
3074 3068
    /**
......
3122 3116
              isXML = false;
3123 3117
            }
3124 3118

  
3125
            logMetacat.warn("Start deleting doc " + docid + "...");
3119
            logMetacat.info("DocumentImpl.delete - Start deleting doc " + docid + "...");
3126 3120
            double start = System.currentTimeMillis()/1000;
3127 3121
            // check for 'write' permission for 'user' to delete this document
3128 3122
            if (!hasAllPermission(user, groups, accnum)) {
......
3138 3132
            // Copy the record to the xml_revisions table
3139 3133
            DocumentImpl.archiveDocAndNodesRevision(conn, docid, user, null);
3140 3134
            double afterArchiveDocAndNode = System.currentTimeMillis()/1000;
3141
            logMetacat.info("The time for archiveDocAndNodesRevision is "+(afterArchiveDocAndNode - start));
3135
            logMetacat.info("DocumentImpl.delete - The time for archiveDocAndNodesRevision is "+(afterArchiveDocAndNode - start));
3142 3136
            // Now delete it from the xml_index table
3143 3137
//            boolean useXMLIndex = (new Boolean(PropertyService
3144 3138
//                    .getProperty("database.usexmlindex"))).booleanValue();
......
3154 3148
            conn.increaseUsageCount(1);
3155 3149
            //}
3156 3150
            double afterDeleteIndex = System.currentTimeMillis()/1000;
3157
            logMetacat.info("The deleting xml_index time is "+(afterDeleteIndex - afterArchiveDocAndNode ));
3151
            logMetacat.info("DocumentImpl.delete - The deleting xml_index time is "+(afterDeleteIndex - afterArchiveDocAndNode ));
3158 3152
            // Now delete it from xml_access table
3159 3153
            pstmt = conn.prepareStatement(
3160 3154
                    "DELETE FROM xml_access WHERE accessfileid = ?");
3161 3155
            pstmt.setString(1, docid);
3162
            logMetacat.debug("running sql: " + pstmt.toString());
3156
            logMetacat.debug("DocumentImpl.delete - running sql: " + pstmt.toString());
3163 3157
            pstmt.execute();
3164 3158
            pstmt.close();
3165 3159
            conn.increaseUsageCount(1);
3166 3160
            double afterDeleteXmlAccess1 = System.currentTimeMillis()/1000;
3167
            logMetacat.info("The deleting xml_access base one accessfileid time is "+(afterDeleteXmlAccess1 - afterDeleteIndex ));
3161
            logMetacat.info("DocumentImpl.delete - The deleting xml_access base one accessfileid time is "+(afterDeleteXmlAccess1 - afterDeleteIndex ));
3168 3162
            pstmt = conn.prepareStatement(
3169 3163
                    "DELETE FROM xml_access WHERE docid = ?");
3170 3164
            pstmt.setString(1, docid);
3171
            logMetacat.debug("running sql: " + pstmt.toString());
3165
            logMetacat.debug("DocumentImpl.delete - running sql: " + pstmt.toString());
3172 3166
            pstmt.execute();
3173 3167
            pstmt.close();
3174 3168
            conn.increaseUsageCount(1);
3175 3169
            double afterDeleteXmlAccess2 = System.currentTimeMillis()/1000;
3176
            logMetacat.info("The deleting xml_access base on docid time is "+(afterDeleteXmlAccess2 - afterDeleteXmlAccess1 ));
3170
            logMetacat.info("DocumentImpl.delete - The deleting xml_access base on docid time is "+(afterDeleteXmlAccess2 - afterDeleteXmlAccess1 ));
3177 3171
            // Delete enteries from xml_queryresult
3178 3172
            pstmt = conn.prepareStatement(
3179 3173
                    "DELETE FROM xml_queryresult WHERE docid = ?");
3180 3174
            pstmt.setString(1, docid);
3181
            logMetacat.debug("running sql: " + pstmt.toString());
3175
            logMetacat.debug("DocumentImpl.delete - running sql: " + pstmt.toString());
3182 3176
            pstmt.execute();
3183 3177
            pstmt.close();
3184 3178
            conn.increaseUsageCount(1);
3185 3179
            double afterDeleteQueryResult = System.currentTimeMillis()/1000;
3186
            logMetacat.info("The deleting xml_queryresult time is "+(afterDeleteQueryResult - afterDeleteXmlAccess2));
3180
            logMetacat.info("DocumentImpl.delete - The deleting xml_queryresult time is "+(afterDeleteQueryResult - afterDeleteXmlAccess2));
3187 3181
            // Delete it from relation table
3188 3182
            pstmt = conn.prepareStatement(
3189 3183
                    "DELETE FROM xml_relation WHERE docid = ?");
3190 3184
            //increase usage count
3191 3185
            pstmt.setString(1, docid);
3192
            logMetacat.debug("running sql: " + pstmt.toString());
3186
            logMetacat.debug("DocumentImpl.delete - running sql: " + pstmt.toString());
3193 3187
            pstmt.execute();
3194 3188
            pstmt.close();
3195 3189
            conn.increaseUsageCount(1);
3196 3190
            double afterXMLRelation = System.currentTimeMillis()/1000;
3197
            logMetacat.info("The deleting time  relation is "+
3191
            logMetacat.info("DocumentImpl.delete - The deleting time  relation is "+
3198 3192
            		(afterXMLRelation - afterDeleteQueryResult) );
3199 3193

  
3200 3194
            // Delete it from xml_path_index table
......
3202 3196
                    "DELETE FROM xml_path_index WHERE docid = ?");
3203 3197
            //increase usage count
3204 3198
            pstmt.setString(1, docid);
3205
            logMetacat.debug("running sql: " + pstmt.toString());
3199
            logMetacat.debug("DocumentImpl.delete - running sql: " + pstmt.toString());
3206 3200
            pstmt.execute();
3207 3201
            pstmt.close();
3208 3202
            conn.increaseUsageCount(1);
......
3213 3207
                    "DELETE FROM xml_accesssubtree WHERE docid = ?");
3214 3208
            //increase usage count
3215 3209
            pstmt.setString(1, docid);
3216
            logMetacat.debug("running sql: " + pstmt.toString());
3210
            logMetacat.debug("DocumentImpl.delete - running sql: " + pstmt.toString());
3217 3211
            pstmt.execute();
3218 3212
            pstmt.close();
3219 3213
            conn.increaseUsageCount(1);
......
3222 3216
            pstmt = conn.prepareStatement(
3223 3217
                    "DELETE FROM xml_documents WHERE docid = ?");
3224 3218
            pstmt.setString(1, docid);
3225
            logMetacat.debug("running sql: " + pstmt.toString());
3219
            logMetacat.debug("DocumentImpl.delete - running sql: " + pstmt.toString());
3226 3220
            pstmt.execute();
3227 3221
            pstmt.close();
3228 3222
            //Usaga count increase 1
3229 3223
            conn.increaseUsageCount(1);
3230 3224
            double afterDeleteDoc = System.currentTimeMillis()/1000;
3231
            logMetacat.info("the time to delete  xml_path_index,  xml_accesssubtree, xml_documents time is "+ 
3225
            logMetacat.info("DocumentImpl.delete - the time to delete  xml_path_index,  xml_accesssubtree, xml_documents time is "+ 
3232 3226
            		(afterDeleteDoc - afterXMLRelation ));
3233 3227
            // Delete the old nodes in xml_nodes table...
3234 3228
                   pstmt = conn.prepareStatement("DELETE FROM xml_nodes "
......
3238 3232
                   conn.increaseUsageCount(1);
3239 3233
                   // Bind the values to the query and execute it
3240 3234
                   pstmt.setString(1, docid);
3241
                   logMetacat.debug("running sql: " + pstmt.toString());
3235
                   logMetacat.debug("DocumentImpl.delete - running sql: " + pstmt.toString());
3242 3236
                   pstmt.execute();
3243 3237
                   pstmt.close();
3244 3238

  
3245 3239
            double afterDeleteXMLNodes = System.currentTimeMillis()/1000;
3246
            logMetacat.info("Deleting xml_nodes time is "+(afterDeleteXMLNodes-afterDeleteDoc));
3240
            logMetacat.info("DocumentImpl.delete - Deleting xml_nodes time is "+(afterDeleteXMLNodes-afterDeleteDoc));
3247 3241
            conn.commit();
3248 3242
            conn.setAutoCommit(true);
3249 3243
        
3250 3244
            // add force delete replcation document here.
3251 3245
            ForceReplicationHandler frh = new ForceReplicationHandler(
3252 3246
                             accnum, ForceReplicationHandler.DELETE, isXML, notifyServer);
3253
            logMetacat.debug("ForceReplicationHandler created: " + frh.toString());
3247
            logMetacat.debug("DocumentImpl.delete - ForceReplicationHandler created: " + frh.toString());
3254 3248
            // clear cache after inserting or updating a document
3255 3249
            if (PropertyService.getProperty("database.queryCacheOn").equals("true"))
3256 3250
            {
......
3258 3252
         	   DBQuery.clearQueryResultCache();
3259 3253
            }
3260 3254
           double end = System.currentTimeMillis()/1000;
3261
           logMetacat.info("total delete time is ===== "+(end - start));
3255
           logMetacat.info("DocumentImpl.delete - total delete time is ===== "+(end - start));
3262 3256

  
3263 3257
        } catch (Exception e) {
3264
            logMetacat.error("error in DocumentImpl.delete: "
3265
                    + e.getMessage());
3258
            logMetacat.error("DocumentImpl.delete - General error: " + e.getMessage());
3266 3259
            throw e;
3267 3260
        } finally {
3268 3261

  
......
3295 3288
      {
3296 3289
        type = result.getString(1);
3297 3290
      }
3298
      logMetacat.warn("The type of deleting docid " + docidWithoutRev +
3291
      logMetacat.debug("DocumentImpl.delete - The type of deleting docid " + docidWithoutRev +
3299 3292
                               " is " + type);
3300 3293
      return type;
3301 3294
    }
......
3361 3354
            String parserName = PropertyService.getProperty("xml.saxparser");
3362 3355
            parser = XMLReaderFactory.createXMLReader(parserName);
3363 3356
            if (ruleBase != null && ruleBase.equals(EML200)) {
3364
                logMetacat.debug("Using eml 2.0.0 parser");
3357
                logMetacat.info("DocumentImpl.initalizeParser - Using eml 2.0.0 parser");
3365 3358
                chandler = new Eml200SAXHandler(dbconn, action, docid, rev,
3366 3359
                        user, groups, pub, serverCode, createDate, updateDate);
3367 3360
                chandler.setIsRevisionDoc(isRevision);
......
3378 3371
                String externalSchemaLocation = null;
3379 3372
//                SchemaLocationResolver resolver = new SchemaLocationResolver();
3380 3373
                externalSchemaLocation = XMLSchemaService.getNameSpaceAndLocationString();
3381
                logMetacat.debug("2.0.0 external schema location: " + externalSchemaLocation);
3374
                logMetacat.debug("DocumentImpl.initalizeParser - 2.0.0 external schema location: " + externalSchemaLocation);
3382 3375
                // Set external schemalocation.
3383 3376
                if (externalSchemaLocation != null
3384 3377
                        && !(externalSchemaLocation.trim()).equals("")) {
3385 3378
                    parser.setProperty(EXTERNALSCHEMALOCATIONPROPERTY,
3386 3379
                            externalSchemaLocation);
3387 3380
                }
3388
                logMetacat.debug("2.0.0 parser configured");
3381
                logMetacat.debug("DocumentImpl.initalizeParser - 2.0.0 parser configured");
3389 3382
            } else if (ruleBase != null && ruleBase.equals(EML210)) {
3390
                logMetacat.debug("Using eml 2.1.0 parser");
3383
                logMetacat.info("DocumentImpl.initalizeParser - Using eml 2.1.0 parser");
3391 3384
                chandler = new Eml210SAXHandler(dbconn, action, docid, rev,
3392 3385
                        user, groups, pub, serverCode, createDate, updateDate);
3393 3386
                chandler.setIsRevisionDoc(isRevision);
......
3403 3396
                // From DB to find the register external schema location
3404 3397
                String externalSchemaLocation = null;
3405 3398
                externalSchemaLocation = XMLSchemaService.getNameSpaceAndLocationString();
3406
                logMetacat.debug("2.1.0 external schema location: " + externalSchemaLocation);
3399
                logMetacat.debug("DocumentImpl.initalizeParser - 2.1.0 external schema location: " + externalSchemaLocation);
3407 3400
                // Set external schemalocation.
3408 3401
                if (externalSchemaLocation != null
3409 3402
                        && !(externalSchemaLocation.trim()).equals("")) {
3410 3403
                    parser.setProperty(EXTERNALSCHEMALOCATIONPROPERTY,
3411 3404
                            externalSchemaLocation);
3412 3405
                }
3413
                logMetacat.debug("Using eml 2.1.0 parser configured");
3406
                logMetacat.debug("DocumentImpl.initalizeParser - Using eml 2.1.0 parser configured");
3414 3407
            } else {
3415 3408
                //create a DBSAXHandler object which has the revision
3416 3409
                // specification
......
3424 3417

  
3425 3418
                if (ruleBase != null && ruleBase.equals(SCHEMA)
3426 3419
                        && needValidation) {
3427
                    logMetacat.warn("Using General schema parser");
3420
                    logMetacat.info("DocumentImpl.initalizeParser - Using General schema parser");
3428 3421
                    // turn on schema validation feature
3429 3422
                    parser.setFeature(VALIDATIONFEATURE, true);
3430 3423
                    parser.setFeature(NAMESPACEFEATURE, true);
......
3440 3433
                    // From DB to find the register external schema location
3441 3434
                    String externalSchemaLocation = null;
3442 3435
                    externalSchemaLocation = XMLSchemaService.getNameSpaceAndLocationString();
3443
                    logMetacat.debug("Generic external schema location: " + externalSchemaLocation);              
3436
                    logMetacat.debug("DocumentImpl.initalizeParser - Generic external schema location: " + externalSchemaLocation);              
3444 3437
                    // Set external schemalocation.
3445 3438
                    if (externalSchemaLocation != null
3446 3439
                            && !(externalSchemaLocation.trim()).equals("")) {
......
3450 3443

  
3451 3444
                } else if (ruleBase != null && ruleBase.equals(DTD)
3452 3445
                        && needValidation) {
3453
                    logMetacat.warn("Using dtd parser");
3446
                    logMetacat.info("DocumentImpl.initalizeParser - Using dtd parser");
3454 3447
                    // turn on dtd validaton feature
3455 3448
                    parser.setFeature(VALIDATIONFEATURE, true);
3456 3449
                    eresolver = new DBEntityResolver(dbconn,
......
3459 3452
                    parser.setEntityResolver((EntityResolver) eresolver);
3460 3453
                    parser.setDTDHandler((DTDHandler) dtdhandler);
3461 3454
                } else {
3462
                    logMetacat.warn("Using other parser");
3455
                    logMetacat.info("DocumentImpl.initalizeParser - Using other parser");
3463 3456
                    // non validation
3464 3457
                    parser.setFeature(VALIDATIONFEATURE, false);
3465 3458
                    eresolver = new DBEntityResolver(dbconn,
......
3501 3494

  
3502 3495
        }catch (Exception e) {
3503 3496
            logMetacat.error(
3504
                    "Error in DocumentImpl.archiveDocRevision : "
3497
                    "DocumentImpl.archiveDocAndNodesRevision - Error in DocumentImpl.archiveDocRevision : "
3505 3498
                            + e.getMessage());
3506 3499
        }
3507 3500
       
......
3548 3541
        pstmt.execute();
3549 3542
        pstmt.close();
3550 3543
        double end = System.currentTimeMillis()/1000;
3551
        logMetacat.info("moving docs from xml_documents to xml_revision takes "+(end -start));
3544
        logMetacat.debug("DocumentImpl.archiveDocAndNodesRevision - moving docs from xml_documents to xml_revision takes "+(end -start));
3552 3545

  
3553 3546
      } catch (SQLException e) {
3554
        logMetacat.error(
3555
                "Error in DocumentImpl.archiveDocAndNodesRevision : "
3547
        logMetacat.error("DocumentImpl.archiveDocAndNodesRevision - SQL error: "
3556 3548
                        + e.getMessage());
3557 3549
        throw e;
3558 3550
      } catch (Exception e) {
3559
        logMetacat.error(
3560
                "Error in DocumentImpl.archiveDocAndNodesRevision : "
3551
        logMetacat.error("DocumentImpl.archiveDocAndNodesRevision - General error: "
3561 3552
                        + e.getMessage());
3562 3553
        throw e;
3563 3554
      }
......
3566 3557
            pstmt.close();
3567 3558
        } catch (SQLException ee) {
3568 3559
            logMetacat.error(
3569
                    "Error in DocumnetImpl.archiveDocRevision: "
3560
                    "DocumentImpl.archiveDocAndNodesRevision - SQL error when closing prepared statement: "
3570 3561
                            + ee.getMessage());
3571 3562
        }
3572 3563
      }
......
3576 3567
    private static void moveNodesToNodesRevision(DBConnection dbconn,
3577 3568
                                       long rootNodeId) throws Exception
3578 3569
    {
3579
        logMetacat.info("the root node id is "+rootNodeId+
3570
        logMetacat.debug("DocumentImpl.moveNodesToNodesRevision - the root node id is "+rootNodeId+
3580 3571
                " will be moved from xml_nodes to xml_node_revision table");
3581 3572
        PreparedStatement pstmt = null;
3582 3573
        double start = System.currentTimeMillis()/1000;
......
3597 3588
        pstmt.execute();
3598 3589
        pstmt.close();
3599 3590
        double end = System.currentTimeMillis()/1000;
3600
        logMetacat.info("moving nodes from xml_nodes to xml_nodes_revision takes "+(end -start));
3591
        logMetacat.debug("DocumentImpl.moveNodesToNodesRevision - Moving nodes from xml_nodes to xml_nodes_revision takes "+(end -start));
3601 3592
        
3602 3593

  
3603 3594
    }
......
3631 3622
            pstmt.close();
3632 3623
        } catch (SQLException e) {
3633 3624
            logMetacat.error(
3634
                    "Error in DocumentImpl.archiveDocRevision : "
3625
                    "DocumentImpl.archiveDocRevision - SQL error: "
3635 3626
                            + e.getMessage());
3636 3627
            throw e;
3637 3628
        } finally {
......
3639 3630
                pstmt.close();
3640 3631
            } catch (SQLException ee) {
3641 3632
                logMetacat.error(
3642
                        "Error in DocumnetImpl.archiveDocRevision: "
3633
                        "DocumentImpl.archiveDocRevision - SQL Error: "
3643 3634
                                + ee.getMessage());
3644 3635
                throw ee;
3645 3636
            } 
......
3670 3661
            try {
3671 3662
                pStmt.close();
3672 3663
            } catch (SQLException e) {
3673
                logMetacat.error(
3674
                        "error in DocumentImpl.deleteXMLDocuments: "
3664
                logMetacat.error("DocumentImpl.deleteXMLDocuments - SQL error: "
3675 3665
                                + e.getMessage());
3676 3666
            } finally {
3677 3667
                //return back DBconnection
......
3728 3718
                pStmt.close();
3729 3719
            }//try
3730 3720
            catch (Exception ee) {
3731
                logMetacat.error(
3732
                        "Error in DocumentImpl.getServerLocationNu(): "
3721
                logMetacat.error("DocumentImpl.getServerLocationNumber - General error: "
3733 3722
                                + ee.getMessage());
3734 3723
            }//catch
3735 3724
            finally {
......
3783 3772
                pStmt.close();
3784 3773
            }
3785 3774
        } catch (Exception e) {
3786
            logMetacat.error("Error in DocumentImpl.getServerCode(): "
3775
            logMetacat.error("DocumentImpl.getServerCode - General Error: "
3787 3776
                    + e.getMessage());
3788 3777
        } finally {
3789 3778
            try {
3790 3779
                pStmt.close();
3791 3780
            } catch (Exception ee) {
3792
                logMetacat.error(
3793
                        "Error in DocumentImpl.getServerCode(): "
3781
                logMetacat.error("DocumentImpl.getServerCode - General error: "
3794 3782
                                + ee.getMessage());
3795 3783
            } finally {
3796 3784
                DBConnectionPool.returnDBConnection(dbConn, serialNumber);
......
3866 3854
            }
3867 3855
        }//try
3868 3856
        catch (Exception e) {
3869
            logMetacat.error(
3870
                    "Error in DocumentImpl.insertServerIntoRepli(): "
3857
            logMetacat.error("DocumentImpl.insertServerIntoReplicationTable - General error: "
3871 3858
                            + e.getMessage());
3872 3859
        }//catch
3873 3860
        finally {
......
3879 3866

  
3880 3867
            }//try
3881 3868
            catch (Exception ee) {
3882
                logMetacat.error(
3883
                        "Error in DocumentImpl.insetServerIntoRepl(): "
3869
                logMetacat.error("DocumentImpl.insertServerIntoReplicationTable - General error: "
3884 3870
                                + ee.getMessage());
3885 3871
            }//catch
3886 3872
            finally {
......
3986 3972
            if (action.equals("READ")) {
3987 3973
                DocumentImpl xmldoc = new DocumentImpl(docid);
3988 3974
                if (useOldReadAlgorithm) {
3989
                    logMetacat.error(xmldoc.readUsingSlowAlgorithm());
3975
                    logMetacat.error("DocumentImpl.main - " + xmldoc.readUsingSlowAlgorithm());
3990 3976
                } else {
3991 3977
                    xmldoc.toXml(new PrintWriter(System.out), null, null, true);
3992 3978
                }
......
4013 3999
            double insertTime = (stopTime - connTime) / 1000;
4014 4000
            double executionTime = (stopTime - startTime) / 1000;
4015 4001
            if (showRuntime) {
4016
                logMetacat.warn("\n\nTotal Execution time was: "
4002
                logMetacat.info("DocumentImpl.main - Total Execution time was: "
4017 4003
                        + executionTime + " seconds.");
4018
                logMetacat.warn("Time to open DB connection was: "
4004
                logMetacat.info("DocumentImpl.main - Time to open DB connection was: "
4019 4005
                        + dbOpenTime + " seconds.");
4020
                logMetacat.warn("Time to insert document was: " + insertTime
4006
                logMetacat.info("DocumentImpl.main - Time to insert document was: " + insertTime
4021 4007
                        + " seconds.");
4022 4008
            }
4023 4009
            dbconn.close();
......
4056 4042
            {
4057 4043
                createDate = DatabaseService.getDBAdapter().toDate(createDate, "YYYY-MM-DD HH24:MI:SS");
4058 4044
            }
4059
            logMetacat.info("the create date is "+createDate);
4045
            logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - the create date is "+createDate);
4060 4046
            if (updateDate == null)
4061 4047
            {
4062 4048
                updateDate = DatabaseService.getDBAdapter().getDateTimeFunction();
......
4065 4051
            {
4066 4052
                updateDate = DatabaseService.getDBAdapter().toDate(updateDate, "YYYY-MM-DD HH24:MI:SS");
4067 4053
            }
4068
            logMetacat.info("the update date is "+updateDate);
4054
            logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - the update date is "+updateDate);
4069 4055
            PreparedStatement pstmt = null;
4070 4056
            String sql = null;
4071
            logMetacat.info("the root node id is "+rootNodeId);
4057
            logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - the root node id is "+rootNodeId);
4072 4058
            if (rootNodeId <= 0)
4073 4059
            {
4074 4060
            	// this is for data file, not rootnodeid need
......
4106 4092

  
4107 4093
            // Bind the values to the query
4108 4094
            pstmt.setString(1, docId);
4109
            logMetacat.info("docid is "+docId);
4095
            logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - docid is "+docId);
4110 4096
            pstmt.setString(2, docName);
4111
            logMetacat.info("docname is "+docName);
4097
            logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - docname is "+docName);
4112 4098
            pstmt.setString(3, docType);
4113
            logMetacat.info("docType is "+docType);
4099
            logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - docType is "+docType);
4114 4100
            pstmt.setString(4, user);
4115
            logMetacat.info("onwer is "+user);
4101
            logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - onwer is "+user);
4116 4102
            pstmt.setString(5, user);
4117
            logMetacat.info("update user is "+user);
4103
            logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - update user is "+user);
4118 4104
            pstmt.setInt(6, 0);
4119 4105
            
4120 4106
            pstmt.setInt(7, serverCode);
4121
            logMetacat.info("server code is "+serverCode);
4107
            logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - server code is "+serverCode);
4122 4108
            pstmt.setInt(8, Integer.parseInt(rev));
4123
            logMetacat.info("rev is "+rev);
4109
            logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - rev is "+rev);
4124 4110
            
4125 4111
            if (rootNodeId >0 )
4126 4112
            {
4127 4113
              if (catalogid != null)
4128 4114
              {
4129 4115
                pstmt.setInt(9, (new Integer(catalogid)).intValue());
4130
                logMetacat.info("catalogid is "+catalogid);
4116
                logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - catalog id is "+catalogid);
4131 4117
                pstmt.setLong(10, rootNodeId);
4132
                logMetacat.info("root id is "+rootNodeId);
4118
                logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - root id is "+rootNodeId);
4133 4119
              }
4134 4120
              else
4135 4121
              {
4136 4122
                 pstmt.setLong(9, rootNodeId);
4137
                 logMetacat.info("root id is "+rootNodeId); 
4123
                 logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - root id is "+rootNodeId); 
4138 4124
              }
4139 4125
            }
4140 4126
            // Do the insertion
4141 4127
            pstmt.execute();
4142 4128
            pstmt.close();
4143
            logMetacat.info("end of write into revisons");
4129
            logMetacat.debug("DocumentImpl.writeDocumentToRevisionTable - end of write into revisons");
4144 4130
           
4145 4131
        } 
4146 4132
        catch (SQLException sqle) 
......
4211 4197
        pstmt.execute();
4212 4198
        pstmt.close(); 
4213 4199
        double end = System.currentTimeMillis()/1000;
4214
        logMetacat.info("The time to delete xml_nodes in UPDATE is "+(end -start));
4200
        logMetacat.info("DocumentImpl.deleteXMLNodes - The time to delete xml_nodes in UPDATE is "+(end -start));
4215 4201
     
4216 4202
    }
4217 4203
}

Also available in: Unified diff