RecallReportPacker.cpp 18.1 KB
Newer Older
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
/******************************************************************************
 *
 * This file is part of the Castor project.
 * See http://castor.web.cern.ch/castor
 *
 * Copyright (C) 2003  CERN
 * This program is free software; you can redistribute it and/or
 * modify it under the terms of the GNU General Public License
 * as published by the Free Software Foundation; either version 2
 * of the License, or (at your option) any later version.
 * This program is distributed in the hope that it will be useful,
 * but WITHOUT ANY WARRANTY; without even the implied warranty of
 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 * GNU General Public License for more details.
 * You should have received a copy of the GNU General Public License
 * along with this program; if not, write to the Free Software
 * Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA.
 *
 * 
 *
 * @author Castor Dev team, castor-dev@cern.ch
 *****************************************************************************/

#include "castor/tape/tapeserver/daemon/RecallReportPacker.hpp"
25
#include "castor/tape/tapeserver/daemon/TaskWatchDog.hpp"
Victor Kotlyar's avatar
Victor Kotlyar committed
26
#include "common/log/Logger.hpp"
27

28
#include <signal.h>
29
#include <iostream>
30
#include <cxxabi.h>
31

32
namespace{
33
  struct failedReportRecallResult : public cta::exception::Exception{
34
35
36
37
    failedReportRecallResult(const std::string& s): Exception(s){}
  };
}

Victor Kotlyar's avatar
Victor Kotlyar committed
38
39
using cta::log::LogContext;
using cta::log::Param;
David COME's avatar
David COME committed
40

41
42
43
44
namespace castor {
namespace tape {
namespace tapeserver {
namespace daemon {
45
46
47
//------------------------------------------------------------------------------
//Constructor
//------------------------------------------------------------------------------
Victor Kotlyar's avatar
Victor Kotlyar committed
48
RecallReportPacker::RecallReportPacker(cta::RetrieveMount *retrieveMount, cta::log::LogContext lc):
49
50
51
52
  ReportPackerInterface<detail::Recall>(lc),
  m_workerThread(*this), m_errorHappened(false), m_retrieveMount(retrieveMount),
  m_tapeThreadComplete(false), m_diskThreadComplete(false)
{
53
  
54
}
55
56
57
//------------------------------------------------------------------------------
//Destructor
//------------------------------------------------------------------------------
58
RecallReportPacker::~RecallReportPacker(){
59
  cta::threading::MutexLocker ml(m_producterProtection);
60
}
61
62
63
//------------------------------------------------------------------------------
//reportCompletedJob
//------------------------------------------------------------------------------
64
65
void RecallReportPacker::reportCompletedJob(std::unique_ptr<cta::RetrieveJob> successfulRetrieveJob){
  std::unique_ptr<Report> rep(new ReportSuccessful(std::move(successfulRetrieveJob)));
66
  cta::threading::MutexLocker ml(m_producterProtection);
67
68
  m_fifo.push(rep.release());
}
69
70
71
//------------------------------------------------------------------------------
//reportFailedJob
//------------------------------------------------------------------------------  
72
73
void RecallReportPacker::reportFailedJob(std::unique_ptr<cta::RetrieveJob> failedRetrieveJob){
  std::unique_ptr<Report> rep(new ReportError(std::move(failedRetrieveJob)));
74
  cta::threading::MutexLocker ml(m_producterProtection);
75
76
  m_fifo.push(rep.release());
}
77
78
79
//------------------------------------------------------------------------------
//reportEndOfSession
//------------------------------------------------------------------------------
80
void RecallReportPacker::reportEndOfSession(){
81
  cta::threading::MutexLocker ml(m_producterProtection);
82
83
  m_fifo.push(new ReportEndofSession());
}
84
85

//------------------------------------------------------------------------------
Daniele Kruse's avatar
Daniele Kruse committed
86
//reportDriveStatus
87
//------------------------------------------------------------------------------
88
void RecallReportPacker::reportDriveStatus(cta::common::dataStructures::DriveStatus status) {
89
  cta::threading::MutexLocker ml(m_producterProtection);
Daniele Kruse's avatar
Daniele Kruse committed
90
  m_fifo.push(new ReportDriveStatus(status));
91
92
}

93
  
94
95
96
//------------------------------------------------------------------------------
//reportEndOfSessionWithErrors
//------------------------------------------------------------------------------
97
void RecallReportPacker::reportEndOfSessionWithErrors(const std::string msg,int error_code){
98
  cta::threading::MutexLocker ml(m_producterProtection);
99
100
  m_fifo.push(new ReportEndofSessionWithErrors(msg,error_code));
}
101

102
103
104
105
106
  
//------------------------------------------------------------------------------
//reportTestGoingToEnd
//------------------------------------------------------------------------------
void RecallReportPacker::reportTestGoingToEnd(){
107
  cta::threading::MutexLocker ml(m_producterProtection);
108
109
110
  m_fifo.push(new ReportTestGoingToEnd());
}

111
112
//------------------------------------------------------------------------------
//ReportSuccessful::execute
113
//------------------------------------------------------------------------------
114
void RecallReportPacker::ReportSuccessful::execute(RecallReportPacker& parent){
115
116
117
118
119
120
121
122
  m_successfulRetrieveJob->asyncComplete();
}

//------------------------------------------------------------------------------
//ReportSuccessful::waitForAsyncExecuteFinished
//------------------------------------------------------------------------------
void RecallReportPacker::ReportSuccessful::waitForAsyncExecuteFinished(){
  m_successfulRetrieveJob->checkComplete();
123
}
124

125
126
127
//------------------------------------------------------------------------------
//ReportEndofSession::execute
//------------------------------------------------------------------------------
128
void RecallReportPacker::ReportEndofSession::execute(RecallReportPacker& parent){
129
  if(!parent.errorHappened()){
Victor Kotlyar's avatar
Victor Kotlyar committed
130
    parent.m_lc.log(cta::log::INFO,"Nominal RecallReportPacker::EndofSession has been reported");
131
    if (parent.m_watchdog) {
Victor Kotlyar's avatar
Victor Kotlyar committed
132
      parent.m_watchdog->addParameter(cta::log::Param("status","success"));
133
134
135
136
      // We have a race condition here between the processing of this message by
      // the initial process and the printing of the end-of-session log, triggered
      // by the end our process. To delay the latter, we sleep half a second here.
      usleep(500*1000);
137
    }
138
139
140
  }
  else {
    const std::string& msg ="RecallReportPacker::EndofSession has been reported  but an error happened somewhere in the process";
Victor Kotlyar's avatar
Victor Kotlyar committed
141
    parent.m_lc.log(cta::log::ERR,msg);
142
    if (parent.m_watchdog) {
Victor Kotlyar's avatar
Victor Kotlyar committed
143
      parent.m_watchdog->addParameter(cta::log::Param("status","failure"));
144
145
146
147
      // We have a race condition here between the processing of this message by
      // the initial process and the printing of the end-of-session log, triggered
      // by the end our process. To delay the latter, we sleep half a second here.
      usleep(500*1000);
148
    }
149
150
151
152
153
154
  }
}

//------------------------------------------------------------------------------
//ReportEndofSession::goingToEnd
//------------------------------------------------------------------------------
155
bool RecallReportPacker::ReportEndofSession::goingToEnd() {
156
  return true;
157
}
158

Daniele Kruse's avatar
Daniele Kruse committed
159
160
161
162
163
//------------------------------------------------------------------------------
//ReportDriveStatus::execute
//------------------------------------------------------------------------------
void RecallReportPacker::ReportDriveStatus::execute(RecallReportPacker& parent){
  parent.m_retrieveMount->setDriveStatus(m_status);
164
  if(m_status==cta::common::dataStructures::DriveStatus::Unmounting) {
165
166
167
    parent.m_retrieveMount->diskComplete();
    parent.m_retrieveMount->tapeComplete();
  }
Daniele Kruse's avatar
Daniele Kruse committed
168
169
170
171
172
}

//------------------------------------------------------------------------------
//ReportDriveStatus::goingToEnd
//------------------------------------------------------------------------------
173
bool RecallReportPacker::ReportDriveStatus::goingToEnd() {
Daniele Kruse's avatar
Daniele Kruse committed
174
175
176
  return false;
}

177
178
179
//------------------------------------------------------------------------------
//ReportEndofSessionWithErrors::execute
//------------------------------------------------------------------------------
180
181
void RecallReportPacker::ReportEndofSessionWithErrors::execute(RecallReportPacker& parent){
  if(parent.m_errorHappened) {
182
    LogContext::ScopedParam(parent.m_lc,Param("errorCode",m_error_code));
Victor Kotlyar's avatar
Victor Kotlyar committed
183
    parent.m_lc.log(cta::log::ERR,m_message);
184
185
  }
  else{
186
    const std::string& msg ="RecallReportPacker::EndofSessionWithErrors has been reported  but NO error was detected during the process";
Victor Kotlyar's avatar
Victor Kotlyar committed
187
    parent.m_lc.log(cta::log::ERR,msg);
188
  }
189
  if (parent.m_watchdog) {
Victor Kotlyar's avatar
Victor Kotlyar committed
190
    parent.m_watchdog->addParameter(cta::log::Param("status","failure"));
191
192
193
194
    // We have a race condition here between the processing of this message by
    // the initial process and the printing of the end-of-session log, triggered
    // by the end our process. To delay the latter, we sleep half a second here.
    usleep(500*1000);
195
  }
196
}
197
198
199
200

//------------------------------------------------------------------------------
//ReportEndofSessionWithErrors::goingToEnd
//------------------------------------------------------------------------------
201
bool RecallReportPacker::ReportEndofSessionWithErrors::goingToEnd() {
202
  return true;
203
204
}

205
206
207
//------------------------------------------------------------------------------
//ReportError::execute
//------------------------------------------------------------------------------
208
209
void RecallReportPacker::ReportError::execute(RecallReportPacker& parent){
  parent.m_errorHappened=true;
Victor Kotlyar's avatar
Victor Kotlyar committed
210
  parent.m_lc.log(cta::log::ERR,m_failedRetrieveJob->failureMessage);
211
  m_failedRetrieveJob->failed(parent.m_lc);
212
}
213

214
//------------------------------------------------------------------------------
215
216
//WorkerThread::WorkerThread
//------------------------------------------------------------------------------
217
218
219
RecallReportPacker::WorkerThread::WorkerThread(RecallReportPacker& parent):
m_parent(parent) {
}
220
221
222
//------------------------------------------------------------------------------
//WorkerThread::run
//------------------------------------------------------------------------------
223
void RecallReportPacker::WorkerThread::run(){
224
  m_parent.m_lc.pushOrReplace(Param("thread", "RecallReportPacker"));
Victor Kotlyar's avatar
Victor Kotlyar committed
225
  m_parent.m_lc.log(cta::log::DEBUG, "Starting RecallReportPacker thread");
226
  bool endFound = false;
227
228
  
  std::list <std::unique_ptr<Report>> reportedSuccessfully;
229
230
231
232
233
  while(1) {
    std::string debugType;
    std::unique_ptr<Report> rep(m_parent.m_fifo.pop());
    {
      cta::log::ScopedParamContainer spc(m_parent.m_lc);
234
235
236
237
238
239
240
241
      int demangleStatus;
      char * demangledReportType = abi::__cxa_demangle(typeid(*rep.get()).name(), nullptr, nullptr, &demangleStatus);
      if (!demangleStatus) {
        spc.add("typeId", demangledReportType);
      } else {
        spc.add("typeId", typeid(*rep.get()).name());
      }
      free(demangledReportType);
242
      if (rep->goingToEnd())
243
244
        spc.add("goingToEnd", "true");
      m_parent.m_lc.log(cta::log::DEBUG, "Popping report");
245
    }
246
247
248
249
250
251
252
253
    // Record whether we found end before calling the potentially exception
    // throwing execute().)
    if (rep->goingToEnd())
      endFound=true;
    // We can afford to see any report to fail and keep passing the following ones
    // as opposed to migrations where one failure fails the session.
    try {
      rep->execute(m_parent);
254
255
256
257
258
259
260
261
262
263
264
      if (typeid(*rep) == typeid(RecallReportPacker::ReportSuccessful)) {
        reportedSuccessfully.emplace_back(std::move(rep)); 
        cta::utils::Timer timing;
        const unsigned int checkedReports = m_parent.flushCheckAndFinishAsyncExecute(reportedSuccessfully);    
        if(checkedReports) {
          cta::log::ScopedParamContainer params(m_parent.m_lc);
          params.add("checkedReports", checkedReports)
                .add("reportingTime", timing.secs());
          m_parent.m_lc.log(cta::log::DEBUG, "After flushCheckAndFinishAsyncExecute()");
        }
      }
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
    } catch(const cta::exception::Exception& e){
      //we get there because to tried to close the connection and it failed
      //either from the catch a few lines above or directly from rep->execute
      cta::log::ScopedParamContainer params(m_parent.m_lc);
      params.add("exceptionWhat", e.getMessageValue())
            .add("exceptionType", typeid(e).name());
      m_parent.m_lc.log(cta::log::ERR, "Tried to report and got a CTA exception.");
      if (m_parent.m_watchdog) {
        m_parent.m_watchdog->addToErrorCount("Error_clientCommunication");
        m_parent.m_watchdog->addParameter(cta::log::Param("status","failure"));
      }
    } catch(const std::exception& e){
      //we get there because to tried to close the connection and it failed
      //either from the catch a few lines above or directly from rep->execute
      cta::log::ScopedParamContainer params(m_parent.m_lc);
      params.add("exceptionWhat", e.what())
            .add("exceptionType", typeid(e).name());
      m_parent.m_lc.log(cta::log::ERR, "Tried to report and got a standard exception.");
      if (m_parent.m_watchdog) {
        m_parent.m_watchdog->addToErrorCount("Error_clientCommunication");
        m_parent.m_watchdog->addParameter(cta::log::Param("status","failure"));
      }
    } catch(...){
      //we get there because to tried to close the connection and it failed
      //either from the catch a few lines above or directly from rep->execute
      m_parent.m_lc.log(cta::log::ERR, "Tried to report and got an unknown exception.");
      if (m_parent.m_watchdog) {
        m_parent.m_watchdog->addToErrorCount("Error_clientCommunication");
        m_parent.m_watchdog->addParameter(cta::log::Param("status","failure"));
      }
295
    }
296
    if (endFound) break;
297
  }
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
  
  try {
    cta::utils::Timer timing;
    const unsigned int checkedReports = m_parent.fullCheckAndFinishAsyncExecute(reportedSuccessfully); 
    if (checkedReports) {
      cta::log::ScopedParamContainer params(m_parent.m_lc);
      params.add("checkedReports", checkedReports)
            .add("reportingTime", timing.secs());
      m_parent.m_lc.log(cta::log::DEBUG, "After fullCheckAndFinishAsyncExecute()");    
    } 
  } catch(const cta::exception::Exception& e){
      cta::log::ScopedParamContainer params(m_parent.m_lc);
      params.add("exceptionWhat", e.getMessageValue())
            .add("exceptionType", typeid(e).name());
      m_parent.m_lc.log(cta::log::ERR, "Tried to report and got a CTA exception.");
      if (m_parent.m_watchdog) {
        m_parent.m_watchdog->addToErrorCount("Error_clientCommunication");
        m_parent.m_watchdog->addParameter(cta::log::Param("status","failure"));
      } 
  } catch(const std::exception& e){
      cta::log::ScopedParamContainer params(m_parent.m_lc);
      params.add("exceptionWhat", e.what())
            .add("exceptionType", typeid(e).name());
      m_parent.m_lc.log(cta::log::ERR, "Tried to report and got a standard exception.");
      if (m_parent.m_watchdog) {
        m_parent.m_watchdog->addToErrorCount("Error_clientCommunication");
        m_parent.m_watchdog->addParameter(cta::log::Param("status","failure"));
      }
  } catch(...){
      m_parent.m_lc.log(cta::log::ERR, "Tried to report and got an unknown exception.");
      if (m_parent.m_watchdog) {
        m_parent.m_watchdog->addToErrorCount("Error_clientCommunication");
        m_parent.m_watchdog->addParameter(cta::log::Param("status","failure"));
      }
  } 
  
334
335
336
337
  // Drain the fifo in case we got an exception
  if (!endFound) {
    while (1) {
      std::unique_ptr<Report> report(m_parent.m_fifo.pop());
338
      if (report->goingToEnd())
339
340
341
        break;
    }
  }
342
343
344
  // Cross check that the queue is indeed empty.
  while (m_parent.m_fifo.size()) {
    // There is at least one extra report we missed.
345
    // The drive status reports are not a problem though.
Victor Kotlyar's avatar
Victor Kotlyar committed
346
    cta::log::ScopedParamContainer spc(m_parent.m_lc);
347
348
349
350
    std::unique_ptr<Report> missedReport(m_parent.m_fifo.pop());
    spc.add("ReportType", typeid(*missedReport).name());
    if (missedReport->goingToEnd())
      spc.add("goingToEnd", "true");
351
352
    if (typeid(*missedReport) != typeid(RecallReportPacker::ReportDriveStatus))
      m_parent.m_lc.log(cta::log::ERR, "Popping missed report (memory leak)");
353
  }
Victor Kotlyar's avatar
Victor Kotlyar committed
354
  m_parent.m_lc.log(cta::log::DEBUG, "Finishing RecallReportPacker thread");
355
}
356
357
358
359
360
361
362
363

//------------------------------------------------------------------------------
//errorHappened()
//------------------------------------------------------------------------------
bool RecallReportPacker::errorHappened() {
  return m_errorHappened || (m_watchdog && m_watchdog->errorHappened());
}

364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
//------------------------------------------------------------------------------
//flushCheckAndFinishAsyncExecute()
//------------------------------------------------------------------------------
unsigned int RecallReportPacker::flushCheckAndFinishAsyncExecute(std::list <std::unique_ptr<Report>> &reportedSuccessfully) {
  unsigned int checkedReports = 0;
  if (reportedSuccessfully.size() >= RECALL_REPORT_PACKER_FLUSH_SIZE) {
    while (!reportedSuccessfully.empty()) {
      std::unique_ptr<Report> report=std::move(reportedSuccessfully.back());
      reportedSuccessfully.pop_back();
      if (!report.get()) continue;
      report->waitForAsyncExecuteFinished();
      checkedReports ++;
    }
  }  
  return checkedReports;
}

//------------------------------------------------------------------------------
//fullCheckAndFinishAsyncExecute()
//------------------------------------------------------------------------------
unsigned int RecallReportPacker::fullCheckAndFinishAsyncExecute(std::list <std::unique_ptr<Report>> &reportedSuccessfully) {
  unsigned int checkedReports = 0;
  while (!reportedSuccessfully.empty()) {
    std::unique_ptr<Report> report=std::move(reportedSuccessfully.back());
    reportedSuccessfully.pop_back();
    if (!report.get()) continue;
    report->waitForAsyncExecuteFinished();
    checkedReports++;
  }
  return checkedReports;
}

396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
//------------------------------------------------------------------------------
//reportTapeDone()
//------------------------------------------------------------------------------
void RecallReportPacker::setTapeDone() {
  m_tapeThreadComplete = true;
}

//------------------------------------------------------------------------------
//reportDiskDone()
//------------------------------------------------------------------------------
void RecallReportPacker::setDiskDone() {
  m_diskThreadComplete = true;
}

//------------------------------------------------------------------------------
//reportDiskDone()
//------------------------------------------------------------------------------
bool RecallReportPacker::allThreadsDone() {
  return m_tapeThreadComplete && m_diskThreadComplete;
}

417
}}}}