void Logger::log(const UTF8String& msg, const category_t& category,
severity_t severity) const
{
if(shouldLog(category, severity)) {
Logger::trace(msg, category, severity);
}
}
void MozJSImplScope::_gcCallback(JSRuntime* rt, JSGCStatus status, void* data) {
if (!shouldLog(logger::LogSeverity::Debug(1))) {
// don't collect stats unless verbose
return;
}
log() << "MozJS GC " << (status == JSGC_BEGIN ? "prologue" : "epilogue") << " heap stats - "
<< " total: " << mongo::sm::get_total_bytes() << " limit: " << mongo::sm::get_max_bytes()
<< std::endl;
}
void shovelerLogMessage(const char *file, int line, ShovelerLogLevel level, const char *message, ...)
{
if(shouldLog(level)) {
va_list va;
va_start(va, message);
GString *assembled = g_string_new("");
g_string_append_vprintf(assembled, message, va);
logCallbackFunction(file, line, level, assembled->str);
g_string_free(assembled, true);
}
}
std::string MozJSScriptEngine::printKnownOps_inlock() {
str::stream out;
if (shouldLog(logger::LogSeverity::Debug(2))) {
out << " known ops: \n";
for (auto&& iSc : _opToScopeMap) {
out << " " << iSc.first << "\n";
}
}
return out;
}
void WiredTigerRecoveryUnit::_txnOpen(OperationContext* opCtx) {
invariant(!_active);
_ensureSession();
// Only start a timer for transaction's lifetime if we're going to log it.
if (shouldLog(kSlowTransactionSeverity)) {
_timer.reset(new Timer());
}
WT_SESSION* s = _session->getSession();
if (_readFromMajorityCommittedSnapshot) {
_majorityCommittedSnapshot =
_sessionCache->snapshotManager().beginTransactionOnCommittedSnapshot(s);
} else {
invariantWTOK(s->begin_transaction(s, NULL));
}
LOG(3) << "WT begin_transaction for snapshot id " << _mySnapshotId;
_active = true;
}
void setSockTimeouts(int sock, double secs) {
bool report = shouldLog(logger::LogSeverity::Debug(4));
DEV report = true;
#if defined(_WIN32)
DWORD timeout = secs * 1000; // Windows timeout is a DWORD, in milliseconds.
int status =
setsockopt(sock, SOL_SOCKET, SO_RCVTIMEO, reinterpret_cast<char*>(&timeout), sizeof(DWORD));
if (report && (status == SOCKET_ERROR))
log() << "unable to set SO_RCVTIMEO: " << errnoWithDescription(WSAGetLastError());
status =
setsockopt(sock, SOL_SOCKET, SO_SNDTIMEO, reinterpret_cast<char*>(&timeout), sizeof(DWORD));
DEV if (report && (status == SOCKET_ERROR)) log() << "unable to set SO_SNDTIMEO: "
<< errnoWithDescription(WSAGetLastError());
#else
struct timeval tv;
tv.tv_sec = (int)secs;
tv.tv_usec = (int)((long long)(secs * 1000 * 1000) % (1000 * 1000));
bool ok = setsockopt(sock, SOL_SOCKET, SO_RCVTIMEO, (char*)&tv, sizeof(tv)) == 0;
if (report && !ok)
log() << "unable to set SO_RCVTIMEO";
ok = setsockopt(sock, SOL_SOCKET, SO_SNDTIMEO, (char*)&tv, sizeof(tv)) == 0;
DEV if (report && !ok) log() << "unable to set SO_SNDTIMEO";
#endif
}
bool Log::logR ( long long now , long type , char *msg , bool asterisk ,
bool forced ) {
// filter if we should
//if ( forced ) goto skipfilter;
// return true if we should not log this
if ( ! forced && ! shouldLog ( type , msg ) ) return true;
// skipfilter:
// can we log if we're a sig handler? don't take changes
if ( g_inSigHandler )
return logLater ( now , type , msg , NULL );
//if ( g_inSigHandler ) return false;
// get "msg"'s length
long msgLen = gbstrlen ( msg );
#ifdef PTHREADS
// lock for threads
pthread_mutex_lock ( &s_lock );
#endif
// do a timestamp, too. use the time synced with host #0 because
// it is easier to debug because all log timestamps are in sync.
if ( now == 0 ) now = gettimeofdayInMillisecondsGlobalNoCore();
// . skip all logging if power out, we do not want to screw things up
// . allow logging for 10 seconds after power out though
if ( ! g_process.m_powerIsOn && now - g_process.m_powerOffTime >10000){
#ifdef PTHREADS
pthread_mutex_unlock ( &s_lock );
#endif
return false;
}
//if ( now == 0 ) now = g_nowApprox;
// chop off any spaces at the end of the msg.
while ( is_wspace_a ( msg [ msgLen - 1 ] ) && msgLen > 0 ) msgLen--;
// get this pid
pid_t pid = getpidtid();
// a tmp buffer
char tt [ MAX_LINE_LEN ];
char *p = tt;
char *pend = tt + MAX_LINE_LEN;
/*
// print timestamp, hostid, type
if ( g_hostdb.m_numHosts <= 999 )
sprintf ( p , "%llu %03li %s ",
now , g_hostdb.m_hostId , getTypeString(type) );
else if ( g_hostdb.m_numHosts <= 9999 )
sprintf ( p , "%llu %04li %s ",
now , g_hostdb.m_hostId , getTypeString(type) );
else if ( g_hostdb.m_numHosts <= 99999 )
sprintf ( p , "%llu %05li %s ",
now , g_hostdb.m_hostId , getTypeString(type) );
*/
// print timestamp, hostid, type
if ( m_logTimestamps ) {
if ( g_hostdb.m_numHosts <= 999 )
sprintf ( p , "%llu %03li ",
now , g_hostdb.m_hostId );
else if ( g_hostdb.m_numHosts <= 9999 )
sprintf ( p , "%llu %04li ",
now , g_hostdb.m_hostId );
else if ( g_hostdb.m_numHosts <= 99999 )
sprintf ( p , "%llu %05li ",
now , g_hostdb.m_hostId );
p += gbstrlen ( p );
}
// msg resource
char *x = msg;
long cc = 7;
// the first 7 bytes or up to the : must be ascii
//while ( p < pend && *x && is_alnum_a(*x) ) { *p++ = *x++; cc--; }
// space pad
//while ( cc-- > 0 ) *p++ = ' ';
// ignore the label for now...
while ( p < pend && *x && is_alnum_a(*x) ) { x++; cc--; }
// thread id if in "thread"
if ( pid != s_pid && s_pid != -1 ) {
//sprintf ( p , "[%li] " , (long)getpid() );
sprintf ( p , "[%lu] " , (unsigned long)pid );
p += gbstrlen ( p );
}
// then message itself
long avail = (MAX_LINE_LEN) - (p - tt) - 1;
if ( msgLen > avail ) msgLen = avail;
if ( *x == ':' ) x++;
if ( *x == ' ' ) x++;
strncpy ( p , x , avail );
// capitalize for consistency. no, makes grepping log msgs harder.
//if ( is_alpha_a(*p) ) *p = to_upper_a(*p);
p += gbstrlen(p);
// back up over spaces
while ( p[-1] == ' ' ) p--;
// end in period or ? or !
//if ( p[-1] != '?' && p[-1] != '.' && p[-1] != '!' )
// *p++ = '.';
*p ='\0';
// the total length, not including the \0
long tlen = p - tt;
// call sprintf, but first make sure we have room in m_buf and in
// the arrays. who know how much room the sprintf is going to need???
// NOTE: TODO: this is shaky -- fix it!
if ( m_bufPtr + tlen >= 1024 * 32 || m_numErrors >= MAX_LOG_MSGS){
// this sets m_bufPtr to 0
if ( ! dumpLog ( ) ) {
fprintf(stderr,"Log::log: could not dump to file!\n");
#ifdef PTHREADS
pthread_mutex_unlock ( &s_lock );
#endif
return false;
}
}
// . filter out nasty chars from the message
// . replace with ~'s
char cs;
char *ttp = tt;
char *ttpend = tt + tlen;
for ( ; ttp < ttpend ; ttp += cs ) {
cs = getUtf8CharSize ( ttp );
if ( is_binary_utf8 ( ttp ) ) {
for ( long k = 0 ; k < cs ; k++ ) *ttp++ = '.';
// careful not to skip the already skipped bytes
cs = 0;
continue;
}
// convert \n's and \r's to spaces
if ( *ttp == '\n' ) *ttp = ' ';
if ( *ttp == '\r' ) *ttp = ' ';
if ( *ttp == '\t' ) *ttp = ' ';
}
if ( m_fd >= 0 ) {
write ( m_fd , tt , tlen );
write ( m_fd , "\n", 1 );
}
else {
// print it out for now
fprintf ( stderr, "%s\n", tt );
}
// set the stuff in the array
m_errorMsg [m_numErrors] = msg;
m_errorMsgLen [m_numErrors] = msgLen;
m_errorTime [m_numErrors] = now;
m_errorType [m_numErrors] = type;
// increase the # of errors
m_numErrors++;
#ifdef PTHREADS
// unlock for threads
pthread_mutex_unlock ( &s_lock );
#endif
return false;
}
void WiredTigerRecoveryUnit::_txnOpen() {
invariant(!_isActive(), toString(_state));
invariant(!_isCommittingOrAborting(),
str::stream() << "commit or rollback handler reopened transaction: "
<< toString(_state));
_ensureSession();
// Only start a timer for transaction's lifetime if we're going to log it.
if (shouldLog(kSlowTransactionSeverity)) {
_timer.reset(new Timer());
}
WT_SESSION* session = _session->getSession();
switch (_timestampReadSource) {
case ReadSource::kUnset:
case ReadSource::kNoTimestamp: {
WiredTigerBeginTxnBlock txnOpen(session, _ignorePrepared);
if (_isOplogReader) {
auto status =
txnOpen.setTimestamp(Timestamp(_oplogManager->getOplogReadTimestamp()),
WiredTigerBeginTxnBlock::RoundToOldest::kRound);
fassert(50771, status);
}
txnOpen.done();
break;
}
case ReadSource::kMajorityCommitted: {
// We reset _majorityCommittedSnapshot to the actual read timestamp used when the
// transaction was started.
_majorityCommittedSnapshot =
_sessionCache->snapshotManager().beginTransactionOnCommittedSnapshot(
session, _ignorePrepared);
break;
}
case ReadSource::kLastApplied: {
if (_sessionCache->snapshotManager().getLocalSnapshot()) {
_readAtTimestamp = _sessionCache->snapshotManager().beginTransactionOnLocalSnapshot(
session, _ignorePrepared);
} else {
WiredTigerBeginTxnBlock(session, _ignorePrepared).done();
}
break;
}
case ReadSource::kAllCommittedSnapshot: {
if (_readAtTimestamp.isNull()) {
_readAtTimestamp = _beginTransactionAtAllCommittedTimestamp(session);
break;
}
// Intentionally continue to the next case to read at the _readAtTimestamp.
}
case ReadSource::kLastAppliedSnapshot: {
// Only ever read the last applied timestamp once, and continue reusing it for
// subsequent transactions.
if (_readAtTimestamp.isNull()) {
_readAtTimestamp = _sessionCache->snapshotManager().beginTransactionOnLocalSnapshot(
session, _ignorePrepared);
break;
}
// Intentionally continue to the next case to read at the _readAtTimestamp.
}
case ReadSource::kProvided: {
WiredTigerBeginTxnBlock txnOpen(session, _ignorePrepared);
auto status = txnOpen.setTimestamp(_readAtTimestamp);
if (!status.isOK() && status.code() == ErrorCodes::BadValue) {
uasserted(ErrorCodes::SnapshotTooOld,
str::stream() << "Read timestamp " << _readAtTimestamp.toString()
<< " is older than the oldest available timestamp.");
}
uassertStatusOK(status);
txnOpen.done();
break;
}
}
LOG(3) << "WT begin_transaction for snapshot id " << _mySnapshotId;
}
void WOLog(int level, const char *format, ...)
{
FILE *log;
va_list ap;
int do_it;
#if defined(TIMESTAMP_LOG_MESSAGES)
struct tm *t;
time_t now;
char timestamp[64];
#endif
if (level < baselevel)
return;
if (! initialized )
return;
do_it = shouldLog();
if ( do_it ) {
/*
* plenty of people have complained that we need to timestamp
* the log entries. the problem is that mktime & friends aren't
* reentrant.
*/
#if defined(TIMESTAMP_LOG_MESSAGES)
WA_lock(logMutex);
time(&now);
t = localtime(&now);
strftime(timestamp, sizeof(timestamp), "%d-%b-%Y %T - ", t);
WA_unlock(logMutex);
#endif
log = fopen(logPath, "a+");
if (log != NULL) {
#if defined(TIMESTAMP_LOG_MESSAGES)
fprintf(log, timestamp);
#endif
fprintf(log,"%s: ", WOLogLevel[level]);
va_start(ap, format);
vfprintf(log, format, ap);
va_end(ap);
fprintf(log,"\n");
fclose(log);
}
}
/*
* if the error is serious, include it into the server's log
*/
#if defined(Netscape) || defined(Apache) || defined(IIS)
if (level == WO_ERR) {
String *str;
str = str_create(NULL, 128);
va_start(ap,format);
str_vappendf(str, format, ap);
va_end(ap);
#if defined(Netscape)
log_error(0,"WebObjects",NULL,NULL,str->text);
#elif defined(Apache)
ap_log_error("WebObjects",0, APLOG_ERR, _webobjects_server, str->text);
#elif defined(IIS)
/*
* again, we're stymied because we don't have a ptr to the
* server struct
* /
{
LPDWORD len = strlen(logstr);
ServerSupportFunction(p->ConnID, HSE_APPEND_LOG_PARAMETER,
str->text, &len, (LPDWORD)NULL);
}
*/
#endif
str_free(str);
}
#endif
}
/*
After insuring that the object isn't in transit, the lookup should querry the dht.
Only called from postingStrand
*/
OSegEntry CraqObjectSegmentation::lookup(const UUID& obj_id)
{
if (mStopping)
return CraqEntry::null();
OSegLookupTraceToken* traceToken = new OSegLookupTraceToken(obj_id,shouldLog());
traceToken->stamp(OSegLookupTraceToken::OSEG_TRACE_INITIAL_LOOKUP_TIME);
++numLookups;
float radius=0;
if (checkOwn(obj_id,&radius)) //this call just checks through to see whether the object is on this space server.
{
++numOnThisServer;
delete traceToken;
return CraqEntry(mContext->id(),radius);
}
//log the request.
CONTEXT_SPACETRACE(objectSegmentationLookupNotOnServerRequest,
obj_id,
mContext->id());
if (checkMigratingFromNotCompleteYet(obj_id,&radius))//this call just checks to see whether the object is migrating from this server to another server. If it is, but hasn't yet received an ack message to disconnect the object connection.
{
++numMigrationNotCompleteYet;
delete traceToken;
return CraqEntry(mContext->id(),radius);
}
traceToken->stamp(OSegLookupTraceToken::OSEG_TRACE_CHECK_CACHE_LOCAL_BEGIN);
CraqEntry cacheReturn = satisfiesCache(obj_id);
if ((cacheReturn.notNull()) && (cacheReturn.server() != mContext->id())) //have to perform second check to prevent accidentally infinitely re-routing to this server when the object doesn't reside here: if the object resided here, then one of the first two conditions would have triggered.
{
CONTEXT_SPACETRACE(osegCacheResponse,
cacheReturn.server(),
obj_id);
++numCacheHits;
traceToken->stamp(OSegLookupTraceToken::OSEG_TRACE_CHECK_CACHE_LOCAL_END);
delete traceToken;
return cacheReturn;
}
traceToken->stamp(OSegLookupTraceToken::OSEG_TRACE_CHECK_CACHE_LOCAL_END);
++mOSegQueueLen;
traceToken->osegQLenPostQuery = mOSegQueueLen;
oStrand->post(boost::bind(&CraqObjectSegmentation::beginCraqLookup,this,obj_id, traceToken));
return CraqEntry::null();
}
bool Log::logR ( int64_t now, int32_t type, const char *msg, bool forced ) {
if ( ! g_loggingEnabled ) {
return true;
}
// return true if we should not log this
if ( ! forced && ! shouldLog ( type , msg ) ) {
return true;
}
// get "msg"'s length
int32_t msgLen = strlen ( msg );
ScopedLock sl(s_lock);
// do a timestamp, too. use the time synced with host #0 because
// it is easier to debug because all log timestamps are in sync.
if ( now == 0 ) now = gettimeofdayInMillisecondsGlobalNoCore();
// . skip all logging if power out, we do not want to screw things up
// . allow logging for 10 seconds after power out though
if ( ! g_process.m_powerIsOn && now - g_process.m_powerOffTime >10000){
return false;
}
// chop off any spaces at the end of the msg.
while ( is_wspace_a ( msg [ msgLen - 1 ] ) && msgLen > 0 ) msgLen--;
// a tmp buffer
char tt [ MAX_LINE_LEN ];
char *p = tt;
if (m_logPrefix) {
if ( m_logTimestamps ) {
if( m_logReadableTimestamps ) {
time_t now_t = (time_t)(now / 1000);
struct tm tm_buf;
struct tm *stm = localtime_r(&now_t,&tm_buf);
p += sprintf ( p , "%04d%02d%02d-%02d%02d%02d-%03d %04" PRId32" ", stm->tm_year+1900,stm->tm_mon+1,stm->tm_mday,stm->tm_hour,stm->tm_min,stm->tm_sec,(int)(now%1000), g_hostdb.m_hostId );
} else {
if ( g_hostdb.getNumHosts() <= 999 )
p += sprintf ( p , "%" PRIu64 " %03" PRId32 " ", (uint64_t)now , g_hostdb.m_hostId );
else if ( g_hostdb.getNumHosts() <= 9999 )
p += sprintf ( p , "%" PRIu64" %04" PRId32" ", (uint64_t)now , g_hostdb.m_hostId );
else if ( g_hostdb.getNumHosts() <= 99999 )
p += sprintf ( p , "%" PRIu64" %05" PRId32" ", (uint64_t)now , g_hostdb.m_hostId );
}
}
// Get thread id. pthread_self instead?
unsigned tid=(unsigned)syscall(SYS_gettid);
p += sprintf(p, "%06u ", tid);
// Log level
p += sprintf(p, "%s ", getTypeString(type));
}
// then message itself
const char *x = msg;
int32_t avail = (MAX_LINE_LEN) - (p - tt) - 1;
if ( msgLen > avail ) msgLen = avail;
if ( *x == ':' ) x++;
if ( *x == ' ' ) x++;
strncpy ( p , x , avail );
// capitalize for consistency. no, makes grepping log msgs harder.
//if ( is_alpha_a(*p) ) *p = to_upper_a(*p);
p += strlen(p);
// back up over spaces
while ( p[-1] == ' ' ) p--;
// end in period or ? or !
//if ( p[-1] != '?' && p[-1] != '.' && p[-1] != '!' )
// *p++ = '.';
*p ='\0';
// the total length, not including the \0
int32_t tlen = p - tt;
// . filter out nasty chars from the message
// . replace with ~'s
char cs;
char *ttp = tt;
char *ttpend = tt + tlen;
for ( ; ttp < ttpend ; ttp += cs ) {
cs = getUtf8CharSize ( ttp );
if ( is_binary_utf8 ( ttp ) ) {
for ( int32_t k = 0 ; k < cs ; k++ ) *ttp++ = '.';
// careful not to skip the already skipped bytes
cs = 0;
continue;
}
}
// . if filesize would be too big then make a new log file
// . should make a new m_fd
if ( m_logFileSize + tlen+1 > MAXLOGFILESIZE && g_conf.m_logToFile )
makeNewLogFile();
if ( m_fd >= 0 ) {
write ( m_fd , tt , tlen );
write ( m_fd , "\n", 1 );
m_logFileSize += tlen + 1;
}
else {
// print it out for now
fprintf ( stderr, "%s\n", tt );
}
return false;
}
/**
* Returns all the IP addresses bound to the network interfaces of this machine.
* This requires a syscall. If the ipv6enabled parameter is true, both IPv6 AND IPv4
* addresses will be returned.
*/
std::vector<std::string> getBoundAddrs(const bool ipv6enabled) {
std::vector<std::string> out;
#ifdef FASTPATH_UNIX
ifaddrs* addrs;
int err = getifaddrs(&addrs);
if (err) {
warning() << "getifaddrs failure: " << errnoWithDescription(err) << std::endl;
return out;
}
ON_BLOCK_EXIT(freeifaddrs, addrs);
// based on example code from linux getifaddrs manpage
for (ifaddrs* addr = addrs; addr != NULL; addr = addr->ifa_next) {
if (addr->ifa_addr == NULL) continue;
int family = addr->ifa_addr->sa_family;
char host[NI_MAXHOST];
if (family == AF_INET || (ipv6enabled && (family == AF_INET6))) {
err = getnameinfo(addr->ifa_addr,
(family == AF_INET ? sizeof(struct sockaddr_in)
: sizeof(struct sockaddr_in6)),
host, NI_MAXHOST, NULL, 0, NI_NUMERICHOST);
if (err) {
warning() << "getnameinfo() failed: " << gai_strerror(err) << std::endl;
continue;
}
out.push_back(host);
}
}
#elif defined(_WIN32)
// Start with the MS recommended 15KB buffer. Use multiple attempts
// for the rare case that the adapter config changes between calls
ULONG adaptersLen = 15 * 1024;
boost::scoped_array<char> buf(new char[adaptersLen]);
IP_ADAPTER_ADDRESSES* adapters = reinterpret_cast<IP_ADAPTER_ADDRESSES*>(buf.get());
DWORD err;
ULONG family = ipv6enabled ? AF_UNSPEC : AF_INET;
for (int tries = 0; tries < 3; ++tries) {
err = GetAdaptersAddresses(family,
GAA_FLAG_SKIP_ANYCAST | // only want unicast addrs
GAA_FLAG_SKIP_MULTICAST |
GAA_FLAG_SKIP_DNS_SERVER,
NULL,
adapters,
&adaptersLen);
if (err == ERROR_BUFFER_OVERFLOW) {
// in this case, adaptersLen will be set to the size we need to allocate
buf.reset(new char[adaptersLen]);
adapters = reinterpret_cast<IP_ADAPTER_ADDRESSES*>(buf.get());
}
else {
break; // only retry for incorrectly sized buffer
}
}
if (err != NO_ERROR) {
warning() << "GetAdaptersAddresses() failed: " << errnoWithDescription(err)
<< std::endl;
return out;
}
for (IP_ADAPTER_ADDRESSES* adapter = adapters;
adapter != NULL; adapter = adapter->Next) {
for (IP_ADAPTER_UNICAST_ADDRESS* addr = adapter->FirstUnicastAddress;
addr != NULL; addr = addr->Next) {
short family =
reinterpret_cast<SOCKADDR_STORAGE*>(addr->Address.lpSockaddr)->ss_family;
if (family == AF_INET) {
// IPv4
SOCKADDR_IN* sock = reinterpret_cast<SOCKADDR_IN*>(addr->Address.lpSockaddr);
char addrstr[INET_ADDRSTRLEN] = {0};
boost::system::error_code ec;
// Not all windows versions have inet_ntop
boost::asio::detail::socket_ops::inet_ntop(AF_INET,
&(sock->sin_addr),
addrstr,
INET_ADDRSTRLEN,
0,
ec);
if (ec) {
warning() << "inet_ntop failed during IPv4 address conversion: "
<< ec.message() << std::endl;
continue;
}
out.push_back(addrstr);
}
else if (family == AF_INET6) {
// IPv6
SOCKADDR_IN6* sock = reinterpret_cast<SOCKADDR_IN6*>(addr->Address.lpSockaddr);
char addrstr[INET6_ADDRSTRLEN] = {0};
boost::system::error_code ec;
boost::asio::detail::socket_ops::inet_ntop(AF_INET6,
&(sock->sin6_addr),
addrstr,
INET6_ADDRSTRLEN,
0,
ec);
if (ec) {
warning() << "inet_ntop failed during IPv6 address conversion: "
<< ec.message() << std::endl;
continue;
}
out.push_back(addrstr);
}
}
}
#endif // defined(_WIN32)
if (shouldLog(logger::LogSeverity::Debug(2))) {
StringBuilder builder;
builder << "getBoundAddrs():";
for (std::vector<std::string>::const_iterator o = out.begin(); o != out.end(); ++o) {
builder << " [ " << *o << "]";
}
LOG(2) << builder.str();
}
return out;
}
