daitss/core — Issue #640: silo service going down for brief periods
Author: lydiam
Created: 2012-03-07 17:47:02+00:00
State: open

After implementing XYMON alerts for silo service downtime, it appears that silo service has been down several times for brief periods in the past week or so.

The following are alert times and snippets of the storage.log (I don't know what else to check):

Case 1:

Wed Mar 7 11:28:30 EST 2012
Tarchive Silo service is DOWN

Snippet from storage.log:
2012 Mar 7 11:27:22 fclnx31 SiloPool[6385]: INFO silos.tarchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 11:27:22] "DELETE /018/data/E20090730_AAACNO " 2
04 - 0.5449
2012 Mar 7 11:27:23 fclnx31 SiloPool[6385]: INFO silos.tarchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 11:27:23] "DELETE /018/data/E20090730_AAACNE " 2
04 - 0.2557
2012 Mar 7 11:27:25 fclnx31 SiloPool[6385]: INFO silos.tarchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 11:27:25] "DELETE /018/data/E20090730_AAACOK " 2
04 - 0.1965
2012 Mar 7 11:27:28 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Using hostname 'silos.tarchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 11:27:29 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Using hostname 'silos.tarchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 11:27:29 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Using hostname 'silos.tarchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 11:27:29 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 11:27:29] "GET /services " 200 21248 0.7141
2012 Mar 7 11:28:06 fclnx31 SiloPool[6461]: INFO silos.tarchive.fcla.edu: Request Received: 787824640 128.227.228.113 - - "POST /create/ER704ZZ0R_GH7UEM.000 HTTP
/1.1"
2012 Mar 7 11:28:31 fclnx31 SiloPool[6385]: INFO silos.tarchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 11:28:31] "GET /018/data/E20090730_AAACMO " 200
362629120 64.6107
2012 Mar 7 11:28:42 fclnx31 SiloPool[6461]: INFO silos.tarchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 11:28:42] "POST /create/ER704ZZ0R_GH7UEM.000 " 2
01 355 36.1492
2012 Mar 7 11:28:43 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 11:28:43] "GET /018/data/E20090730_AAACNA " 200
360222720 68.1576
2012 Mar 7 11:28:45 fclnx31 SiloPool[6376]: INFO silos.tarchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 11:28:45] "GET /018/data/E20090730_AAACNM " 200
374374400 77.5272
2012 Mar 7 11:28:59 fclnx31 SiloPool[6376]: INFO silos.tarchive.fcla.edu: Request Received: 3204454400 128.227.228.113 - - "POST /create/ES9IG74ZJ_IOI7S4.000 HTT
P/1.1"
2012 Mar 7 11:30:32 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Using hostname 'silos.tarchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 11:30:32 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Using hostname 'silos.tarchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 11:30:32 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Using hostname 'silos.tarchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 11:30:32 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 11:30:32] "GET /services " 200 21248 0.7412
2012 Mar 7 11:30:56 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Using hostname 'silos.tarchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 11:30:57 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Using hostname 'silos.tarchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 11:30:57 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Using hostname 'silos.tarchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 11:30:57 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 11:30:57] "GET /services " 200 21248 0.7808
2012 Mar 7 11:30:57 fclnx31 SiloPool[6390]: INFO silos.tarchive.fcla.edu: Request Received: 362485760 128.227.228.113 - - "POST /create/E20090730_AAACMO.000 HTTP
/1.1"

Case 2:

Wed Mar 7 01:43:50 EST 2012
Darchive Silo service is DOWN

Snippet from storage.log:

2012 Mar 7 01:43:23 fclnx30 SiloPool[31996]: INFO silos.darchive.fcla.edu: Request Received: 997857280 128.227.228.113 - - "POST /create/EVJ8KEYCP_J9MKG0.000 HTTP/1.1"
2012 Mar 7 01:43:33 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Using hostname 'silos.darchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 01:43:33 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Using hostname 'silos.darchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 01:43:34 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Using hostname 'silos.darchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 01:43:34 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 01:43:34] "GET /services " 200 21248 0.7620
2012 Mar 7 01:43:35 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Using hostname 'silos.darchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 01:43:36 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Using hostname 'silos.darchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 01:43:36 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Using hostname 'silos.darchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 01:43:36 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 01:43:36] "GET /services " 200 21248 0.7650
2012 Mar 7 01:43:36 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Using hostname 'silos.darchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 01:43:37 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Using hostname 'silos.darchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 01:43:37 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Using hostname 'silos.darchive.fcla.edu' for silo lookup: 73 silos found.
2012 Mar 7 01:43:37 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 01:43:37] "GET /services " 200 21248 0.6507
2012 Mar 7 01:43:38 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Request Received: 132331520 128.227.228.113 - - "POST /create/E20090730_AAABHC.000 HTTP/1.1"
2012 Mar 7 01:43:41 fclnx30 SiloPool[31830]: INFO silos.darchive.fcla.edu: Request Received: 138342400 128.227.228.113 - - "POST /create/E20090730_AAABHA.000 HTTP/1.1"
2012 Mar 7 01:43:41 fclnx30 SiloPool[32024]: INFO silos.darchive.fcla.edu: Request Received: 131768320 128.227.228.113 - - "POST /create/E20090730_AAABHE.000 HTTP/1.1"
2012 Mar 7 01:44:03 fclnx30 SiloPool[31784]: INFO silos.darchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 01:44:03] "POST /create/E20090730_AAABHC.000 " 201 355 25.2566
2012 Mar 7 01:44:03 fclnx30 SiloPool[32024]: INFO silos.darchive.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 01:44:03] "POST /create/E20090730_AAABHE.000 " 201 355 22.0669
2012 Mar 7 01:44:03 fclnx30 StorageMaster[32231]: INFO storage-master.fda.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 01:44:03] "PUT /packages/E20090730_AAABHC.000 " 201 310 50.1587
2012 Mar 7 01:44:03 fclnx30 StorageMaster[32267]: INFO storage-master.fda.fcla.edu: Rack: 128.227.228.113 - - [07/Mar/2012 01:44:03] "PUT /packages/E20090730_AAABHE.000 " 201 310 43.6368

Other reported downtime from XYMON, without the storage.log snippets:

Thu Mar 1 23:00:39 EST 2012
Tarchive Silo service is DOWN

I wasn't able to find other instances of silo service being down, but XYMON is so full of false positive describe service alerts that I may be missing some.

I'm wondering if this is telling us that we're running too many concurrent processes and that silo service is too busy to give
a timely status response.

We're currently running 3 d1refreshes and 2 ingests concurrently.