Tomcat Catalina.out

The catalina.out log records events and conditions that affect Tomcat's operation. The following provides interpretations of some of the messages in the log.

Error
  1. Error while processing payload 0
    1. ORA-00904:  invalid identifier: This generally means a user error trying to read something that doesn't exist, nothing for operators to worry about.
      FrontierProd 11/17/09 09:49:59.120 CET +0100 id=169212 Error while processing payload 0:
      java.lang.Exception: While querying "CMS_COND_21X_ALIGNMENT"."POOL_OR_MAPPING_ELEMENTS": ORA-00904: "VARIABLE_PAR_INDEX": invalid identifier
              at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:145)
              at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:331)
      
    2. ClientAbortException: This means the client dropped the connection, also a pretty common occurrence and nothing to worry about, most likely the client timed out. The cause for the timeout might be a problem but the abort exception isn't.
      FrontierProd 10/30/09 05:46:49.925 CET +0100 id=9316185 Error while processing payload 0:
      ClientAbortException:  java.net.SocketException: Broken pipe
              at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:366)
      
    3. ORA-00942: table or view does not exist: This is also a user error, asking for a table that doesn't exist, usually nothing for operators to be concerned about
      FrontierInt 11/09/09 17:04:25.121 CET +0100 id=793335 Error while processing payload 0:
      java.lang.Exception: While querying "CMS_COND_30X_HCAL"."POOL_OR_CLASS_VERSIONS": ORA-00942: table or view does not exist
              at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:145)
              at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:331)
      
  2. Error getting last-modified time | table not found in CMS_FRONTIER_MODS.LAST_MODIFIED: This usually means that the schema/username doesn't exist yet. Usually nothing for operators to worry about unless a user asks what it means.
    FrontierInt 11/06/09 09:27:16.950 CET +0100 id=674587 Error getting last-modified time:
    java.lang.Exception: CMS_COND_31X_GLOBALTAG.ALL_TABLES not found in CMS_FRONTIER_MODS.LAST_MODIFIED
            at gov.fnal.frontier.SQLTimes.getLastModified(SQLTimes.java:87)
    
  3. Error initializing Frontier object
    1. X-frontier-id header missing: Real frontier clients always insert X-frontier-id http header, so this means someone is using wget or something like that without adding that header. Operators don't need to be concerned unless there's a lot of them or a user asks what it means.
      FrontierProd 10/20/09 23:00:54.513 CEST +0200 id=571056 servlet_version:3.18 start threads:1 query type=frontier_request:1:DEFAULT&encoding=BLOBzip&p1=eNorTs1JTS5RsLS0VEgrys9VSClNzAEASF raddr 127.0.0.1 frontier-id: missing via: 1.1 vocms63.cern.ch:8000 (squid/2.7.STABLE5) x-forwarded-for: 128.141.136.42
      FrontierProd 10/20/09 23:00:54.513 CEST +0200 id=571056 Error initializing Frontier object:
      java.lang.Exception: X-frontier-id header missing
              at gov.fnal.frontier.Frontier.logClientDesc(Frontier.java:260)
      
    2. no query: This also means a user is not using a real frontier client, although they did know enough to put in X-frontier-id.
      dwdtest 11/12/09 03:00:00.371 CET +0100 id=1 Error initializing Frontier object:
      java.lang.Exception: no query
              at gov.fnal.frontier.Frontier.logClientDesc(Frontier.java:230)
      
  4. Error acquiring database: That's a database configuration error, ask DB Administrators.
    FrontierPrep 11/10/09 00:56:01.027 CET +0100 id=98557 Error acquiring database:
    java.sql.SQLException: ORA-00257: archiver error. Connect internal only, until freed.
            at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:145)
    
Warning or SEVERE or Failed
  1. DB acquire keepalive giving up: This means that it took too long (typically more than 5 minutes) to acquire a connection. There can be a lot of different reasons, requires log analysis to find out the root cause.
    FrontierProd 11/11/09 20:41:34.170 CET +0100 id=906036-ka DB acquire sent keepalive 60
    FrontierProd 11/11/09 20:41:34.170 CET +0100 id=906036-ka DB acquire keepalive giving up
    
  2. SEVERE: That means the server was too busy. Requires log analysis to find out the root cause.
    FrontierProd 11/11/09 20:41:37.451 CET +0100 id=906200-ka DB acquire sent keepalive 5
    Nov 11, 2009 8:41:37 PM org.apache.tomcat.util.threads.ThreadPool logFull
    SEVERE: All threads (150) are currently busy, waiting. Increase maxThreads (150) or check the servlet status
    FrontierProd 11/11/09 20:41:37.582 CET +0100 id=906109-ka DB acquire sent keepalive 51
    
  3. Failed: As long as tomcat has indeed stopped, it doesn't really matter.
    Nov 11, 2009 9:20:11 PM org.apache.catalina.core.AprLifecycleListener lifecycleEvent
    INFO: Failed shutdown of Apache Portable Runtime
    Nov 11, 2009 9:20:24 PM org.apache.catalina.core.AprLifecycleListener lifecycleEvent
    
  4. Request for a non-existent file. Missing file prevents checking if-modified-since time.
    smallfiles 07/31/22 05:52:30.869 CEST +0200 id=84 servlet_version:3.41 start threads:1 query /type=frontier_file:1:DEFAULT&encoding=BLOB&p1=slc6_amd64_gcc472/13TeV/madgraph/V5_2.2.1/dyellell01234j_5f_LO_MLM/v1/10 raddr 127.0.0.1 frontier-id: CMSSW_8_0_X_2022-07-31-0000 2.9.1 12575 cmsbld(501) cmsbld via: 1.0 vocms0224.cern.ch/3 (squid/frontier-squid-4.17-1.1), 1.1 vocms0279.cern.ch/0 (squid/frontier-squid-4.17-1.1) x-forwarded-for: 2001:1458:301:c9::100:107, 188.184.18.5
    smallfiles 07/31/22 05:52:30.869 CEST +0200 id=84 if-modified-since: Sun, 24 Jul 2022 04:27:49 GMT
    smallfiles 07/31/22 05:52:30.889 CEST +0200 id=84 Cannot read path /data/fileserve/smallfiles/slc6_amd64_gcc472/13TeV/madgraph/V5_2.2.1/dyellell01234j_5f_LO_MLM/v1/10
    smallfiles 07/31/22 05:52:30.889 CEST +0200 id=84 Error getting cached last-modified time:
    java.lang.Exception: Cannot read file slc6_amd64_gcc472/13TeV/madgraph/V5_2.2.1/dyellell01234j_5f_LO_MLM/v1/10
    smallfiles 07/31/22 05:52:30.889 CEST +0200 id=84 stop threads=1 msecs=20
    
Normal operation messages
  1. Successful initialization of data source
    not_set 06/14/22 18:27:11.433 CEST +0200 FrontierInit Initializing Frontier servlet version 3.41
    Frontier 06/14/22 18:27:11.444 CEST +0200 FrontierInit max threads: 100
    Frontier 06/14/22 18:27:11.444 CEST +0200 FrontierInit send stale if error: true
    Frontier 06/14/22 18:27:11.444 CEST +0200 FrontierInit validate last-modified secs: 300
    Frontier 06/14/22 18:27:11.444 CEST +0200 FrontierInit last-modified table name: CMS_FRONTIER_MODS.LAST_MODIFIED
    Frontier 06/14/22 18:27:11.444 CEST +0200 FrontierInit long hour: null, long secs: 21000
    Frontier 06/14/22 18:27:11.444 CEST +0200 FrontierInit short hour: null, short secs: 21000
    
  2. Successful query that reads from cache that is up-to-date.
    PromptProd 08/11/22 00:02:00.348 CEST +0200 id=106754713 servlet_version:3.41 start threads:1 query /type=frontier_request:1:DEFAULT&encoding=BLOBzip5&p1=eNpdjk1rAjEQhv9KyMVLKdWKtx6mk1Fjd5NlM1i2l2GRHISskbj.f1lEFnp9Ht6PQBUhK82w0..abU3CXUP67YX894GQ-8HQOdy33tk-YOvdLMgZ8Vs5QmWN5W4WFQR.YmAyMg3Nsmk9E05Ngt6QVtvW10pjHQS9M3YyYboHO-3MqN89tfTKO6hJqy.1OMQRcynxNObS9KUf4hjLDXNK8TSe80XCfRhiWW5k9RnidfWx3EBKx7UYYBD4WWOf8kI9AGPGTMI_&ttl=short raddr 127.0.0.1 frontier-id: wmagent_PromptReco_Run357001_ParkingSingleMuon2 2.9.1 575 nobody(99) /DC=ch/DC=cern/OU=computers/CN=tier0/vocms001.cern.ch/CN=389035645/CN=2000869032 via: 1.0 fu-c2a02-45-02/1 (squid/frontier-squid-4.13-3.1), 1.1 ucsrv-c2f46-32-14/squid (squid/frontier-squid-4.13-3.1), 1.1 vocms0279.cern.ch/0 (squid/frontier-squid-4.17-1.1) x-forwarded-for: 10.29.0.161, 10.176.14.147, 10.184.32.84
    PromptProd 08/11/22 00:02:00.348 CEST +0200 id=106754713 if-modified-since: Wed, 10 Aug 2022 21:33:06 GMT
    PromptProd 08/11/22 00:02:00.348 CEST +0200 id=106754713 SQL [SELECT "TAG"."TIME_TYPE", "TAG"."OBJECT_TYPE", "TAG"."SYNCHRONIZATION", "TAG"."END_OF_VALIDITY", "TAG"."LAST_VALIDATED_TIME", "TAG"."PROTECTION_CODE" FROM "CMS_CONDITIONS"."TAG" "TAG" WHERE "TAG"."NAME" = 'JetCorrectorParametersCollection_Summer16_23Sep2016AllV4_DATA_AK4Calo' ]
    PromptProd 08/11/22 00:02:00.348 CEST +0200 id=106754713 using cached last-modified time of CMS_CONDITIONS.TAG
    PromptProd 08/11/22 00:02:00.348 CEST +0200 id=106754713 not modified (cached)
    PromptProd 08/11/22 00:02:00.348 CEST +0200 id=106754713 stop threads=1 msecs=0
    
  3. Successful query to DB that is needed because cache was out-of-date.
    FrontierProd 08/11/22 00:01:50.355 CEST +0200 id=277836590 servlet_version:3.41 start threads:2 query /type=frontier_request:1:DEFAULT&encoding=BLOBzip5&p1=eNplkFFLwzAUhf-KJS9Zxda0djKLe4hJugZMUnKzjT6FKRUGs45tvvjrpVUfxJfLvfDdczgH1ZMSAaTGoK0IYLSdEe02JCOorVAkgdo7A0QYjMJZqYN2Fkk2QfA9t43yCn7eAl9Fy40isATav.wObS0OH.dLfxLvp00RlYrHV9x-9rfxeHneD3l863dDLObDmQJwK3.FtEXlR7cY9Cj3sITgph0DN.2MFixfpGyRsjvI51VZVuU9vaZd13WpMamU0DRFWRldIWZ1TROAlXfrFh47EBzD35w3OWMMOIK2AZKr6XJeKj-i-1v5AmR9UVM_&ttl=short raddr 127.0.0.1 frontier-id: wmagent_pdmvserv_task_BPH-RunIIFall18GS-00425__v1_T_220426_121928_1075 2.9.1 409 cmsgli(44702) /DC=ch/DC=cern/OU=Organic Units/OU=Users/CN=amaltaro/CN=718748/CN=Alan Malta Rodrigues/CN=743311021/CN=1885170807/CN=1950468509/CN=2595191105/CN=105766127 via: 1.0 cmssrvz12.fnal.gov/1 (squid/frontier-squid-4.15-1.2.osg36.el7), 1.1 vocms0279.cern.ch/0 (squid/frontier-squid-4.17-1.1) x-forwarded-for: 131.225.190.51, 131.225.189.3
    FrontierProd 08/11/22 00:01:50.355 CEST +0200 id=277836590 if-modified-since: Wed, 10 Aug 2022 16:05:05 GMT
    FrontierProd 08/11/22 00:01:50.355 CEST +0200 id=277836590 SQL [SELECT DISTINCT MIN("IOV"."SINCE") FROM "CMS_CONDITIONS"."IOV" "IOV" WHERE "IOV"."TAG_NAME" = 'ecalPFClusterCorV2_EE_pfSize3_ptbin1_mean_25ns'  AND "IOV"."INSERTION_TIME" <= TO_TIMESTAMP('2018-08-06 15:44:49','YYYY-MM-DD HH24:MI:SS.FF')  GROUP BY CAST("IOV"."SINCE"/1000 AS INT )*1000 ORDER BY MIN("IOV"."SINCE")]
    FrontierProd 08/11/22 00:01:50.355 CEST +0200 id=277836590 using cached last-modified time of CMS_CONDITIONS.IOV
    FrontierProd 08/11/22 00:01:50.355 CEST +0200 id=277836590 modified at time: Wed, 10 Aug 2022 21:57:05 GMT (cached)
    FrontierProd 08/11/22 00:01:50.355 CEST +0200 id=277836590 Acquiring DB connection lock
    FrontierProd 08/11/22 00:01:50.355 CEST +0200 id=277836590 Acquiring DB connection
    FrontierProd 08/11/22 00:01:50.477 CEST +0200 id=277836590 DB connection acquired active=1 msecs=122
    FrontierProd 08/11/22 00:01:50.477 CEST +0200 id=277836590 Executing DB query
    FrontierProd 08/11/22 00:01:50.478 CEST +0200 id=277836590 DB query finished msecs=1
    FrontierProd 08/11/22 00:01:50.478 CEST +0200 id=277836590 DB data transferred msecs=0
    FrontierProd 08/11/22 00:01:50.478 CEST +0200 id=277836590 rows=1, full size=42
    FrontierProd 08/11/22 00:01:50.478 CEST +0200 id=277836590 DB connection released remaining=1
    FrontierProd 08/11/22 00:01:50.478 CEST +0200 id=277836590 stop threads=2 msecs=1152
    
  4. Successful query that has to fetch last-modified time and finds up-to-date cache it can use.
    PromptProd 08/13/22 00:05:51.812 CEST +0200 id=28764001 servlet_version:3.41 start threads:1 query /type=frontier_request:1:DEFAULT&encoding=BLOBzip5&p1=eNpdjk0KwjAQRq8SsnEj4gVcjMm0jTSZkgxK3WRjoIWC0oD0.BJKKbh9j.8nYIuKhWSo5UmysRi571AeN0TXGyr.g6F3qvHkzBPYkNsFOh2pindojTbc76KFwCsGRh3L0C47T4yqNEVFGqWoPFkhlQ1RkdOmmFDuQS3XjHg06HHLO7AoxUUcwtiNS5pgGnmYUx7e0yvHtHzmlHP8ng-iB8guQIA_&ttl=short raddr 127.0.0.1 frontier-id: wmagent_Express_Run357401_StreamCalibration 2.9.1 566 cmsplt23(81243) /DC=ch/DC=cern/OU=computers/CN=tier0/vocms001.cern.ch/CN=1788194201/CN=1961733374 via: 1.0 vocms0224.cern.ch/3 (squid/frontier-squid-4.17-1.1), 1.1 vocms0219.cern.ch/0 (squid/frontier-squid-4.17-1.1) x-forwarded-for: 128.142.240.108, 188.184.18.5
    PromptProd 08/13/22 00:05:51.812 CEST +0200 id=28764001 if-modified-since: Fri, 12 Aug 2022 21:40:35 GMT
    PromptProd 08/13/22 00:05:51.812 CEST +0200 id=28764001 SQL [SELECT "TAG"."TIME_TYPE", "TAG"."OBJECT_TYPE", "TAG"."SYNCHRONIZATION", "TAG"."END_OF_VALIDITY", "TAG"."LAST_VALIDATED_TIME", "TAG"."PROTECTION_CODE" FROM "CMS_CONDITIONS"."TAG" "TAG" WHERE "TAG"."NAME" = 'SiPixelAliThresholds_express_v0' ]
    PromptProd 08/13/22 00:05:51.812 CEST +0200 id=28764001 Acquiring DB connection lock
    PromptProd 08/13/22 00:05:51.812 CEST +0200 id=28764001 Acquiring DB connection
    PromptProd 08/13/22 00:05:51.812 CEST +0200 id=28764001 DB connection acquired active=1 msecs=0
    PromptProd 08/13/22 00:05:51.812 CEST +0200 id=28764001 getting last-modified time of CMS_CONDITIONS.TAG
    PromptProd 08/13/22 00:05:51.814 CEST +0200 id=28764001 not modified
    PromptProd 08/13/22 00:05:51.814 CEST +0200 id=28764001 DB connection released remaining=0
    PromptProd 08/13/22 00:05:51.814 CEST +0200 id=28764001 stop threads=1 msecs=2
    
  5. Successful query that has to fetch last-modified time and finds cache out-of-date so it has to query the DB.
    FrontierProd 08/13/22 00:01:41.023 CEST +0200 id=59902125 servlet_version:3.41 start threads:1 query /type=frontier_request:1:DEFAULT&encoding=BLOBzip5&p1=eNpVjLEOgyAURX-l5S0ujRHQqkMHis9oI2CApHEiGuT-P6Fba9d7zrmeFlIBcJXbYuWAJQ4ySLxdFx8cSU0uzma0-8g.X6RCDNtKCKOzGlBpH5U1wxxmazyWX-vXwXsiR9efSfoJ4QFFyomnvT1OwZo9iYqztukz72ue2ZnvrK4E69qjK.ADU3gvPg__&ttl=forever raddr 127.0.0.1 frontier-id: CMSSW_12_4_3 2.9.1 162 sconsueg(104954) /C=DE/O=GermanGrid/OU=DESY/CN=Sandra Consuegra-Rodriguez/CN=410572398 via: 1.0 vocms0223.cern.ch/3 (squid/frontier-squid-4.17-1.1), 1.1 vocms0219.cern.ch/0 (squid/frontier-squid-4.17-1.1) x-forwarded-for: 128.142.132.157, 188.184.48.91
    FrontierProd 08/13/22 00:01:41.023 CEST +0200 id=59902125 SQL [SELECT "PAYLOAD"."DATA", "PAYLOAD"."STREAMER_INFO", "PAYLOAD"."OBJECT_TYPE" FROM "CMS_CONDITIONS"."PAYLOAD" "PAYLOAD" WHERE "PAYLOAD"."HASH" = 'dfd2da7be315ad3021759f2942f1ef61403187b8' ]
    FrontierProd 08/13/22 00:01:41.023 CEST +0200 id=59902125 Acquiring DB connection lock
    FrontierProd 08/13/22 00:01:41.023 CEST +0200 id=59902125 Acquiring DB connection
    FrontierProd 08/13/22 00:01:41.024 CEST +0200 id=59902125 DB connection acquired active=1 msecs=1
    FrontierProd 08/13/22 00:01:41.024 CEST +0200 id=59902125 getting last-modified time of CMS_CONDITIONS.PAYLOAD
    FrontierProd 08/13/22 00:01:41.026 CEST +0200 id=59902125 last-modified time: Fri, 12 Aug 2022 21:57:05 GMT
    FrontierProd 08/13/22 00:01:41.026 CEST +0200 id=59902125 Executing DB query
    FrontierProd 08/13/22 00:01:41.027 CEST +0200 id=59902125 DB query finished msecs=1
    FrontierProd 08/13/22 00:01:41.027 CEST +0200 id=59902125 DB data transferred msecs=0
    FrontierProd 08/13/22 00:01:41.027 CEST +0200 id=59902125 rows=1, full size=455
    FrontierProd 08/13/22 00:01:41.027 CEST +0200 id=59902125 DB connection released remaining=0
    FrontierProd 08/13/22 00:01:41.027 CEST +0200 id=59902125 stop threads=1 msecs=4
    
  6. Query that returns no rows. It is up to the user to interpret the result.
    PromptProd 08/12/22 00:05:02.103 CEST +0200 id=107308651 servlet_version:3.41 start threads:1 query /type=frontier_request:1:DEFAULT&encoding=BLOBzip5&p1=eNoLdvVxdQ5RUErOLY5Pzs9LySzJzM8rjg9wjPTxd3SJz4g3VFLgcgvy91XQCIYoRVWppwRVqqSXkVicoeAYTIxZuMxQ4Ar3cA1yJWCHj6e3q4K9JkxxkH.4X6ivgo2tgr1VanJiTkpycUl.eWpRcUliSWlxfH5eTmZeqqqVEQDKfEuv raddr 127.0.0.1 frontier-id: CMSSW_12_3_X_2022-08-11-2300 2.9.1 27158 cmsbld(501) cmsbld via: 1.0 vocms0223.cern.ch/4 (squid/frontier-squid-4.17-1.1), 1.1 vocms0279.cern.ch/0 (squid/frontier-squid-4.17-1.1) x-forwarded-for: 2001:1458:301:cb::100:2ce, 188.184.48.91
    PromptProd 08/12/22 00:05:02.103 CEST +0200 id=107308651 if-modified-since: Thu, 11 Aug 2022 05:59:09 GMT
    PromptProd 08/12/22 00:05:02.103 CEST +0200 id=107308651 SQL [SELECT "cms_conditions_PAYLOAD_h_1" 
    FROM (SELECT cms_conditions."PAYLOAD".hash AS "cms_conditions_PAYLOAD_h_1" 
    FROM cms_conditions."PAYLOAD" 
    WHERE cms_conditions."PAYLOAD".hash LIKE ?) 
    WHERE ROWNUM <= ?:ecaldcstowerstatus_online%:2]
    PromptProd 08/12/22 00:05:02.103 CEST +0200 id=107308651 Acquiring DB connection lock
    PromptProd 08/12/22 00:05:02.103 CEST +0200 id=107308651 Acquiring DB connection
    PromptProd 08/12/22 00:05:02.103 CEST +0200 id=107308651 DB connection acquired active=1 msecs=0
    PromptProd 08/12/22 00:05:02.103 CEST +0200 id=107308651 Executing DB query
    PromptProd 08/12/22 00:05:02.104 CEST +0200 id=107308651 DB query finished msecs=1
    PromptProd 08/12/22 00:05:02.104 CEST +0200 id=107308651 DB data transferred msecs=0
    PromptProd 08/12/22 00:05:02.104 CEST +0200 id=107308651 rows=0, full size=41
    PromptProd 08/12/22 00:05:02.104 CEST +0200 id=107308651 empty response, setting max age and payload max age to 300
    PromptProd 08/12/22 00:05:02.104 CEST +0200 id=107308651 DB connection released remaining=0
    PromptProd 08/12/22 00:05:02.104 CEST +0200 id=107308651 stop threads=1 msecs=1
    
-- CarlVuosalo - 2022-08-10
Edit | Attach | Watch | Print version | History: r8 | r6 < r5 < r4 < r3 | Backlinks | Raw View | Raw edit | More topic actions...
Topic revision: r4 - 2022-08-13 - CarlVuosalo
 
    • Cern Search Icon Cern Search
    • TWiki Search Icon TWiki Search
    • Google Search Icon Google Search

    Frontier All webs login

This site is powered by the TWiki collaboration platform Powered by PerlCopyright & 2008-2022 by the contributing authors. All material on this collaboration platform is the property of the contributing authors.
or Ideas, requests, problems regarding TWiki? use Discourse or Send feedback