Tomcat catalina.out

The catalina.out log records events and conditions that affect Tomcat's operation. The fields in this log are as follows:

• Application or resource that produced this log entry
• Timestamp of entry
• Tag for related entries -- Entries from the same operation will share the same tag
• Message detail

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
   

Explanation of message components

1. frontier-id, which is composed of several fields:
   1. CMSSW version or WMAgent ID string
   2. Frontier client API version number
   3. Frontier process ID
   4. User ID, both string and number, for request
   5. Distinguished Name of user or user name string
2. via is a standard HTTP header that shows protocol and proxy information in a comma-separated list, with each element of the list having this format:
   1. Protocol version number
   2. Public proxy URL and port number
   3. Frontier-Squid version string for proxy
3. x-forwarded-for is a standard HTTP header that shows the IP addresses of:
   1. The client
   2. First proxy
   3. Second or final proxy, if any

1. threads: The number of servlet threads performing parallel requests at that time
2. active: The current number of active parallel DB connections when connection acquired
3. remaining: The remaining number of active parallel DB connections when a connection finishes
4. DB connection acquired msecs: The number of milliseconds it took to acquire the DB connection lock and DB connection
5. DB query finished msecs: The number of milliseconds it took to execute the DB query
6. DB data transferred msecs: The number of milliseconds it took to transfer query data after execution
7. rows: The number of database rows returned from the query
8. full size: The number of uncompressed bytes returned from the query
9. stop msecs: The total number of milliseconds that the request took

-- CarlVuosalo - 2022-08-10