1
2 #include "meta.h"
3
4 #include <unistd.h>
5 #include <string.h>
6 #include <errno.h>
7 #include <sys/time.h>
8 #include <dirent.h>
9
10 #include "debug.h"
11 #include "aclogger.h"
12 #include "acfg.h"
13 #include "lockable.h"
14 #include "filereader.h"
15 #include "fileio.h"
16
17 #include <vector>
18 #include <deque>
19 #include <iostream>
20 #include <fstream>
21 #include <atomic>
22
23 using namespace std;
24
25 namespace acng
26 {
27 namespace log
28 {
29
30 ofstream fErr, fStat;
31 static acmutex mx;
32
33 bool logIsEnabled = false;
34
35 std::atomic<off_t> totalIn(0), totalOut(0);
36
GetCurrentCountersInOut()37 std::pair<off_t,off_t> GetCurrentCountersInOut()
38 {
39 return std::make_pair(totalIn.load(), totalOut.load());
40 }
41
42 std::pair<off_t,off_t> oldCounters(0,0);
43
ResetOldCounters()44 void ResetOldCounters()
45 {
46 char lbuf[600];
47 // safe some cycles an snprintf
48 auto xl = (CACHE_BASE.size() + cfg::privStoreRelQstatsSfx.size());
49 if (xl > 550)
50 return; // heh?
51 memcpy(lbuf, CACHE_BASE.data(), CACHE_BASE.size());
52 memcpy(lbuf + CACHE_BASE.size(), cfg::privStoreRelQstatsSfx.data(),
53 cfg::privStoreRelQstatsSfx.size());
54
55 for (char foldNam :
56 { 'i', 'o' })
57 {
58 lbuf[xl] = 0;
59 auto xoff = sprintf(lbuf + xl, "/%c/", foldNam);
60 auto lptr = lbuf + xl + xoff;
61 auto dirp = opendir(lbuf);
62 if (!dirp)
63 continue;
64 while (true)
65 {
66 auto ent = readdir(dirp);
67 if (!ent)
68 break;
69 auto llen = strlen(ent->d_name);
70 if (llen > 25 || llen < 4)
71 continue;
72 memcpy(lptr, ent->d_name, llen + 1);
73 unlink(lbuf);
74 }
75 closedir(dirp);
76 }
77 oldCounters = decltype(oldCounters)();
78 }
79
GetOldCountersInOut(bool calcIncomming,bool calcOutgoing)80 decltype(oldCounters) GetOldCountersInOut(bool calcIncomming, bool calcOutgoing)
81 {
82 #ifndef MINIBUILD
83 // needs to do first reading of old stats?
84 char lbuf[600];
85 // safe some cycles an snprintf
86 auto xl=(CACHE_BASE.size() + cfg::privStoreRelQstatsSfx.size());
87 if(xl > 550)
88 return oldCounters; // heh?
89 memcpy(lbuf, CACHE_BASE.data(), CACHE_BASE.size());
90 memcpy(lbuf+CACHE_BASE.size(), cfg::privStoreRelQstatsSfx.data(), cfg::privStoreRelQstatsSfx.size());
91 if (!oldCounters.first && !oldCounters.second)
92 {
93 auto rfunc = [&lbuf, xl](off_t& pRet, char foldNam)
94 {
95 lbuf[xl]=0;
96 auto xoff=sprintf(lbuf+xl, "/%c/", foldNam);
97 auto lptr = lbuf+xl+xoff;
98 auto dirp = opendir(lbuf);
99 if(!dirp)
100 return;
101 char buf[30];
102 while(true)
103 {
104 auto ent = readdir(dirp);
105 if(!ent) break;
106 auto llen=strlen(ent->d_name);
107 if(llen > 25 || llen<4) continue;
108 memcpy(lptr, ent->d_name, llen+1);
109 auto tpos=readlink(lbuf, buf, _countof(buf)-1);
110 if(tpos < 1) continue;
111 buf[tpos]=0;
112 pRet += acng::strsizeToOfft(buf);
113 }
114 closedir(dirp);
115 };
116 if(calcIncomming)
117 rfunc(oldCounters.first, 'i');
118 if(calcOutgoing)
119 rfunc(oldCounters.second, 'o');
120 }
121 #endif
122 return oldCounters;
123 }
124
open()125 bool open()
126 {
127 // only called in the beginning or when reopening, already locked...
128 // lockguard g(&mx);
129
130 if(cfg::logdir.empty())
131 return true;
132
133 logIsEnabled = true;
134
135 string apath(cfg::logdir+"/apt-cacher.log"), epath(cfg::logdir+"/apt-cacher.err");
136
137 mkbasedir(apath);
138
139 if(fErr.is_open())
140 fErr.close();
141 if(fStat.is_open())
142 fStat.close();
143
144 fErr.open(epath.c_str(), ios::out | ios::app);
145 fStat.open(apath.c_str(), ios::out | ios::app);
146
147 return fStat.is_open() && fErr.is_open();
148 }
149
transfer(uint64_t bytesIn,uint64_t bytesOut,cmstring & sClient,cmstring & sPath,bool bAsError)150 void transfer(uint64_t bytesIn,
151 uint64_t bytesOut,
152 cmstring& sClient,
153 cmstring& sPath,
154 bool bAsError)
155 {
156 totalIn.fetch_add(bytesIn);
157 totalOut.fetch_add(bytesOut);
158
159 if(!logIsEnabled)
160 return;
161
162 lockguard g(&mx);
163
164 if(!fStat.is_open())
165 return;
166 auto tNow=GetTime();
167 if (bytesIn)
168 {
169 fStat << tNow << "|I|" << bytesIn;
170 if (cfg::verboselog)
171 fStat << '|' << sClient << '|' << sPath;
172 fStat << '\n'; // not endl, it might flush
173 }
174 if (bytesOut)
175 {
176 fStat << tNow << (bAsError ? "|E|" : "|O|") << bytesOut;
177 if (cfg::verboselog)
178 fStat << '|' << sClient << '|' << sPath;
179 fStat << '\n'; // not endl, it might flush
180 }
181
182 if(cfg::debug & LOG_FLUSH) fStat.flush();
183 }
184
misc(const string & sLine,const char cLogType)185 void misc(const string & sLine, const char cLogType)
186 {
187 if(!logIsEnabled)
188 return;
189
190 lockguard g(&mx);
191 if(!fStat.is_open())
192 return;
193
194 fStat << time(0) << '|' << cLogType << '|' << sLine << '\n';
195
196 if(cfg::debug & LOG_FLUSH)
197 fStat.flush();
198 }
199
err(const char * msg,const char * client)200 void err(const char *msg, const char *client)
201 {
202 if(!logIsEnabled)
203 return;
204
205 lockguard g(&mx);
206
207 if(!fErr.is_open())
208 {
209 #ifdef DEBUG // basic debugging of acngtool
210 cerr << msg <<endl;
211 #endif
212 return;
213 }
214
215 static char buf[32];
216 const time_t tm=time(nullptr);
217 ctime_r(&tm, buf);
218 buf[24]=0;
219 fErr << buf << '|';
220 if(client)
221 fErr << client << ": ";
222 fErr << msg << '\n';
223
224 #ifdef DEBUG
225 if(cfg::debug & log::LOG_DEBUG)
226 cerr << buf << msg <<endl;
227 #endif
228
229 if(cfg::debug & log::LOG_DEBUG)
230 fErr.flush();
231 }
232
flush()233 void flush()
234 {
235 if(!logIsEnabled)
236 return;
237
238 lockguard g(mx);
239 if(fErr.is_open()) fErr.flush();
240 if(fStat.is_open()) fStat.flush();
241 }
242
close(bool bReopen)243 void close(bool bReopen)
244 {
245 // let's try to store a snapshot of the current stats
246 auto snapIn = offttos(totalIn.exchange(0));
247 auto snapOut = offttos(totalOut.exchange(0));
248 timeval tp;
249 gettimeofday(&tp, 0);
250 auto inLinkPath = CACHE_BASE + cfg::privStoreRelQstatsSfx + "/i/"
251 + acng::offttos(tp.tv_sec) + "." + acng::ltos(tp.tv_usec);
252 auto outLinkPath = CACHE_BASE + cfg::privStoreRelQstatsSfx + "/o/"
253 + acng::offttos(tp.tv_sec) + "." + acng::ltos(tp.tv_usec);
254 ignore_value(symlink(snapIn.c_str(), inLinkPath.c_str()));
255 ignore_value(symlink(snapOut.c_str(), outLinkPath.c_str()));
256
257
258 if(!logIsEnabled)
259 return;
260
261 lockguard g(mx);
262 if(cfg::debug >= LOG_MORE) cerr << (bReopen ? "Reopening logs...\n" : "Closing logs...\n");
263 fErr.close();
264 fStat.close();
265 if(bReopen)
266 log::open();
267 }
268
269
270 #define DAYSECONDS (3600*24)
271 #define WEEKSECONDS (DAYSECONDS * 7)
272
273 #ifndef MINIBUILD
GetStats()274 inline deque<tRowData> GetStats()
275 {
276 string sDataFile=cfg::cachedir+SZPATHSEP"_stats_dat";
277 deque<tRowData> out;
278
279 time_t now = time(nullptr);
280
281 for (int i = 0; i < 7; i++)
282 {
283 tRowData d;
284 d.to = now - i * DAYSECONDS;
285 d.from = d.to - DAYSECONDS;
286 out.emplace_back(d);
287 }
288
289 for (auto& log : ExpandFilePattern(cfg::logdir + SZPATHSEP "apt-cacher*.log", false))
290 {
291 if (cfg::debug >= LOG_MORE)
292 cerr << "Reading log file: " << log << endl;
293 filereader reader;
294 if (!reader.OpenFile(log))
295 {
296 log::err("Error opening a log file");
297 continue;
298 }
299 string sLine;
300 tStrVec tokens;
301
302 while (reader.GetOneLine(sLine))
303 {
304 // cout << "got line: " << sLine <<endl;
305 tokens.clear();
306 if (Tokenize(sLine, "|", tokens) < 3)
307 continue;
308
309 // cout << "having: " << tokens[0] << ", " << tokens[1] << ", " << tokens[2]<<endl;
310
311 time_t when = strtoul(tokens[0].c_str(), 0, 10);
312 if (when > out.front().to || when < out.back().from)
313 continue;
314
315 for (auto it = out.rbegin(); it != out.rend(); it++)
316 {
317 if (when < it->from || when > it->to)
318 continue;
319
320 unsigned long dcount = strtoul(tokens[2].c_str(), 0, 10);
321 switch (*tokens[1].c_str())
322 {
323 case ('I'):
324 it->byteIn += dcount;
325 it->reqIn++;
326 break;
327 case ('O'):
328 it->byteOut += dcount;
329 it->reqOut++;
330 break;
331 default:
332 continue;
333 }
334 }
335 }
336 }
337 return out;
338 }
339
340
GetStatReport()341 string GetStatReport()
342 {
343 string ret;
344 vector<char> buf(1024);
345 for (auto& entry : log::GetStats())
346 {
347 auto reqMax = std::max(entry.reqIn, entry.reqOut);
348 auto dataMax = std::max(entry.byteIn, entry.byteOut);
349
350 if (0 == dataMax || 0 == reqMax)
351 continue;
352
353 char tbuf[50];
354 size_t zlen(0);
355 ctime_r(&entry.from, tbuf);
356 struct tm *tmp = localtime(&entry.from);
357 if (!tmp)
358 goto time_error;
359 zlen = strftime(tbuf, sizeof(tbuf), TIMEFORMAT, tmp);
360 if (!zlen)
361 goto time_error;
362
363 if (entry.from != entry.to)
364 {
365 tmp = localtime(&entry.to);
366 if (!tmp)
367 goto time_error;
368 if (0 == strftime(tbuf + zlen, sizeof(tbuf) - zlen,
369 " - " TIMEFORMAT, tmp))
370 goto time_error;
371 }
372 snprintf(&buf[0], buf.size(), "<tr bgcolor=\"white\">"
373
374 "<td class=\"colcont\">%s</td>"
375
376 "<td class=\"coltitle\"><span> </span></td>"
377
378 "<td class=\"colcont\">%lu (%2.2f%%)</td>"
379 "<td class=\"colcont\">%lu (%2.2f%%)</td>"
380 "<td class=\"colcont\">%lu</td>"
381
382 "<td class=\"coltitle\"><span> </span></td>"
383
384 "<td class=\"colcont\">%2.2f MiB (%2.2f%%)</td>"
385 "<td class=\"colcont\">%2.2f MiB (%2.2f%%)</td>"
386 "<td class=\"colcont\">%2.2f MiB</td>"
387 "</tr>", tbuf, reqMax - entry.reqIn, double(reqMax - entry.reqIn)
388 / reqMax * 100, // hitcount
389 entry.reqIn, double(entry.reqIn) / reqMax * 100, // misscount
390 reqMax,
391
392 double(dataMax - entry.byteIn) / 1048576, double(dataMax
393 - entry.byteIn) / dataMax * 100, // hitdata
394 double(entry.byteIn) / 1048576, double(entry.byteIn) / dataMax
395 * 100, // missdata
396 double(dataMax) / 1048576
397
398 ); //, int(entry.ratioSent*nRatWid), int((1.0-entry.ratioSent)*nRatWid));
399 ret += &buf[0];
400 continue;
401 time_error: ret
402 += " Invalid time value detected, check the stats database. ";
403 }
404 return ret;
405 }
406 #endif
407 }
408
409 // let the compiler decide between GNU and XSI version
add_msg(int r,int err,const char * buf,mstring * p)410 inline void add_msg(int r, int err, const char* buf, mstring *p)
411 {
412 if(r)
413 p->append(tSS() << "UNKNOWN ERROR: " << err);
414 else
415 p->append(buf);
416 }
417
add_msg(const char * msg,int,const char *,mstring * p)418 inline void add_msg(const char *msg, int , const char* , mstring *p)
419 {
420 p->append(msg);
421 }
422
tErrnoFmter(const char * prefix)423 tErrnoFmter::tErrnoFmter(const char *prefix)
424 {
425 int err=errno;
426 char buf[64];
427 buf[0]=buf[sizeof(buf)-1]=0x0;
428 if(prefix)
429 assign(prefix);
430 add_msg(strerror_r(err, buf, sizeof(buf)-1), err, buf, this);
431 }
432
433 #ifdef DEBUG
434
435 static struct : public base_with_mutex, public std::map<pthread_t, int>
436 {} indentPerThread;
437
t_logger(const char * szFuncName,const void * ptr)438 t_logger::t_logger(const char *szFuncName, const void * ptr)
439 {
440 m_id = pthread_self();
441 m_szName = szFuncName;
442 callobj = uintptr_t(ptr);
443 {
444 lockguard __lockguard(indentPerThread);
445 m_nLevel = indentPerThread[m_id]++;
446 }
447 // writing to the level of parent since it's being "created there"
448 GetFmter() << ">> " << szFuncName << " [T:"<<m_id<<" P:0x"<< tSS::hex<< callobj << tSS::dec <<"]";
449 Write();
450 m_nLevel++;
451 }
452
~t_logger()453 t_logger::~t_logger()
454 {
455 m_nLevel--;
456 GetFmter() << "<< " << m_szName << " [T:"<<m_id<<" P:0x"<< tSS::hex<< callobj << tSS::dec <<"]";
457 Write();
458 lockguard __lockguard(indentPerThread);
459 indentPerThread[m_id]--;
460 if(0 == indentPerThread[m_id])
461 indentPerThread.erase(m_id);
462 }
463
GetFmter()464 tSS & t_logger::GetFmter()
465 {
466 m_strm.clear();
467 for(unsigned i=0;i<m_nLevel;i++)
468 m_strm << "\t";
469 m_strm<< " - ";
470 return m_strm;
471 }
472
Write(const char * pFile,unsigned int nLine)473 void t_logger::Write(const char *pFile, unsigned int nLine)
474 {
475 if(pFile)
476 {
477 const char *p=strrchr(pFile, CPATHSEP);
478 pFile=p?(p+1):pFile;
479 m_strm << " [T:" << m_id << " S:" << pFile << ":" << tSS::dec << nLine
480 <<" P:0x"<< tSS::hex<< callobj << tSS::dec <<"]";
481 }
482 log::err(m_strm.c_str());
483 }
484
485 #endif
486
487 }
488