1 // -*- mode:C++; tab-width:8; c-basic-offset:2; indent-tabs-mode:t -*-
2 // vim: ts=8 sw=2 smarttab
4 * Ceph - scalable distributed file system
6 * Copyright (C) 2004-2006 Sage Weil <sage@newdream.net>
8 * This is free software; you can redistribute it and/or
9 * modify it under the terms of the GNU Lesser General Public
10 * License version 2.1, as published by the Free Software
11 * Foundation. See file COPYING.
15 #include <boost/algorithm/string/predicate.hpp>
20 #include "LogMonitor.h"
22 #include "MonitorDBStore.h"
24 #include "messages/MMonCommand.h"
25 #include "messages/MLog.h"
26 #include "messages/MLogAck.h"
27 #include "common/Graylog.h"
28 #include "common/errno.h"
29 #include "common/strtol.h"
30 #include "include/assert.h"
31 #include "include/str_list.h"
32 #include "include/str_map.h"
33 #include "include/compat.h"
35 #define dout_subsys ceph_subsys_mon
37 #define dout_prefix _prefix(_dout, mon, get_last_committed())
38 static ostream
& _prefix(std::ostream
*_dout
, Monitor
*mon
, version_t v
) {
39 return *_dout
<< "mon." << mon
->name
<< "@" << mon
->rank
40 << "(" << mon
->get_state_name()
41 << ").log v" << v
<< " ";
44 ostream
& operator<<(ostream
&out
, const LogMonitor
&pm
)
50 Tick function to update the map based on performance every N seconds
53 void LogMonitor::tick()
55 if (!is_active()) return;
57 dout(10) << *this << dendl
;
61 void LogMonitor::create_initial()
63 dout(10) << "create_initial -- creating initial map" << dendl
;
65 memset(&e
.who
, 0, sizeof(e
.who
));
66 e
.name
= g_conf
->name
;
67 e
.stamp
= ceph_clock_now();
70 ss
<< "mkfs " << mon
->monmap
->get_fsid();
73 pending_log
.insert(pair
<utime_t
,LogEntry
>(e
.stamp
, e
));
76 void LogMonitor::update_from_paxos(bool *need_bootstrap
)
78 dout(10) << __func__
<< dendl
;
79 version_t version
= get_last_committed();
80 dout(10) << __func__
<< " version " << version
81 << " summary v " << summary
.version
<< dendl
;
82 if (version
== summary
.version
)
84 assert(version
>= summary
.version
);
86 map
<string
,bufferlist
> channel_blog
;
88 version_t latest_full
= get_version_latest_full();
89 dout(10) << __func__
<< " latest full " << latest_full
<< dendl
;
90 if ((latest_full
> 0) && (latest_full
> summary
.version
)) {
92 get_version_full(latest_full
, latest_bl
);
93 assert(latest_bl
.length() != 0);
94 dout(7) << __func__
<< " loading summary e" << latest_full
<< dendl
;
95 bufferlist::iterator p
= latest_bl
.begin();
97 dout(7) << __func__
<< " loaded summary e" << summary
.version
<< dendl
;
100 // walk through incrementals
101 while (version
> summary
.version
) {
103 int err
= get_version(summary
.version
+1, bl
);
107 bufferlist::iterator p
= bl
.begin();
113 dout(7) << "update_from_paxos applying incremental log " << summary
.version
+1 << " " << le
<< dendl
;
115 string channel
= le
.channel
;
116 if (channel
.empty()) // keep retrocompatibility
117 channel
= CLOG_CHANNEL_CLUSTER
;
119 if (channels
.do_log_to_syslog(channel
)) {
120 string level
= channels
.get_level(channel
);
121 string facility
= channels
.get_facility(channel
);
122 if (level
.empty() || facility
.empty()) {
123 derr
<< __func__
<< " unable to log to syslog -- level or facility"
124 << " not defined (level: " << level
<< ", facility: "
125 << facility
<< ")" << dendl
;
128 le
.log_to_syslog(channels
.get_level(channel
),
129 channels
.get_facility(channel
));
132 if (channels
.do_log_to_graylog(channel
)) {
133 ceph::logging::Graylog::Ref graylog
= channels
.get_graylog(channel
);
135 graylog
->log_log_entry(&le
);
137 dout(7) << "graylog: " << channel
<< " " << graylog
138 << " host:" << channels
.log_to_graylog_host
<< dendl
;
141 string log_file
= channels
.get_log_file(channel
);
142 dout(20) << __func__
<< " logging for channel '" << channel
143 << "' to file '" << log_file
<< "'" << dendl
;
145 if (!log_file
.empty()) {
146 string log_file_level
= channels
.get_log_file_level(channel
);
147 if (log_file_level
.empty()) {
148 dout(1) << __func__
<< " warning: log file level not defined for"
149 << " channel '" << channel
<< "' yet a log file is --"
150 << " will assume lowest level possible" << dendl
;
153 int min
= string_to_syslog_level(log_file_level
);
154 int l
= clog_type_to_syslog_level(le
.prio
);
159 bufferlist
&blog
= channel_blog
[channel
];
160 blog
.append(ss
.str());
168 summary
.prune(g_conf
->mon_log_max_summary
);
171 dout(15) << __func__
<< " logging for "
172 << channel_blog
.size() << " channels" << dendl
;
173 for(map
<string
,bufferlist
>::iterator p
= channel_blog
.begin();
174 p
!= channel_blog
.end(); ++p
) {
175 if (!p
->second
.length()) {
176 dout(15) << __func__
<< " channel '" << p
->first
177 << "': nothing to log" << dendl
;
181 dout(15) << __func__
<< " channel '" << p
->first
182 << "' logging " << p
->second
.length() << " bytes" << dendl
;
183 string log_file
= channels
.get_log_file(p
->first
);
185 int fd
= ::open(log_file
.c_str(), O_WRONLY
|O_APPEND
|O_CREAT
, 0600);
188 dout(1) << "unable to write to '" << log_file
<< "' for channel '"
189 << p
->first
<< "': " << cpp_strerror(err
) << dendl
;
191 int err
= p
->second
.write_fd(fd
);
193 dout(1) << "error writing to '" << log_file
<< "' for channel '"
194 << p
->first
<< ": " << cpp_strerror(err
) << dendl
;
196 VOID_TEMP_FAILURE_RETRY(::close(fd
));
203 void LogMonitor::create_pending()
206 pending_summary
= summary
;
207 dout(10) << "create_pending v " << (get_last_committed() + 1) << dendl
;
210 void LogMonitor::encode_pending(MonitorDBStore::TransactionRef t
)
212 version_t version
= get_last_committed() + 1;
214 dout(10) << __func__
<< " v" << version
<< dendl
;
217 multimap
<utime_t
,LogEntry
>::iterator p
;
218 for (p
= pending_log
.begin(); p
!= pending_log
.end(); ++p
)
219 p
->second
.encode(bl
, mon
->get_quorum_con_features());
221 put_version(t
, version
, bl
);
222 put_last_committed(t
, version
);
225 void LogMonitor::encode_full(MonitorDBStore::TransactionRef t
)
227 dout(10) << __func__
<< " log v " << summary
.version
<< dendl
;
228 assert(get_last_committed() == summary
.version
);
230 bufferlist summary_bl
;
231 ::encode(summary
, summary_bl
, mon
->get_quorum_con_features());
233 put_version_full(t
, summary
.version
, summary_bl
);
234 put_version_latest_full(t
, summary
.version
);
237 version_t
LogMonitor::get_trim_to()
239 if (!mon
->is_leader())
242 unsigned max
= g_conf
->mon_max_log_epochs
;
243 version_t version
= get_last_committed();
245 return version
- max
;
249 bool LogMonitor::preprocess_query(MonOpRequestRef op
)
251 op
->mark_logmon_event("preprocess_query");
252 PaxosServiceMessage
*m
= static_cast<PaxosServiceMessage
*>(op
->get_req());
253 dout(10) << "preprocess_query " << *m
<< " from " << m
->get_orig_source_inst() << dendl
;
254 switch (m
->get_type()) {
255 case MSG_MON_COMMAND
:
256 return preprocess_command(op
);
259 return preprocess_log(op
);
267 bool LogMonitor::prepare_update(MonOpRequestRef op
)
269 op
->mark_logmon_event("prepare_update");
270 PaxosServiceMessage
*m
= static_cast<PaxosServiceMessage
*>(op
->get_req());
271 dout(10) << "prepare_update " << *m
<< " from " << m
->get_orig_source_inst() << dendl
;
272 switch (m
->get_type()) {
273 case MSG_MON_COMMAND
:
274 return prepare_command(op
);
276 return prepare_log(op
);
283 bool LogMonitor::preprocess_log(MonOpRequestRef op
)
285 op
->mark_logmon_event("preprocess_log");
286 MLog
*m
= static_cast<MLog
*>(op
->get_req());
287 dout(10) << "preprocess_log " << *m
<< " from " << m
->get_orig_source() << dendl
;
290 MonSession
*session
= m
->get_session();
293 if (!session
->is_capable("log", MON_CAP_W
)) {
294 dout(0) << "preprocess_log got MLog from entity with insufficient privileges "
295 << session
->caps
<< dendl
;
299 for (deque
<LogEntry
>::iterator p
= m
->entries
.begin();
300 p
!= m
->entries
.end();
302 if (!pending_summary
.contains(p
->key()))
306 dout(10) << " nothing new" << dendl
;
316 struct LogMonitor::C_Log
: public C_MonOp
{
318 C_Log(LogMonitor
*p
, MonOpRequestRef o
) :
319 C_MonOp(o
), logmon(p
) {}
320 void _finish(int r
) override
{
321 if (r
== -ECANCELED
) {
324 logmon
->_updated_log(op
);
328 bool LogMonitor::prepare_log(MonOpRequestRef op
)
330 op
->mark_logmon_event("prepare_log");
331 MLog
*m
= static_cast<MLog
*>(op
->get_req());
332 dout(10) << "prepare_log " << *m
<< " from " << m
->get_orig_source() << dendl
;
334 if (m
->fsid
!= mon
->monmap
->fsid
) {
335 dout(0) << "handle_log on fsid " << m
->fsid
<< " != " << mon
->monmap
->fsid
340 for (deque
<LogEntry
>::iterator p
= m
->entries
.begin();
341 p
!= m
->entries
.end();
343 dout(10) << " logging " << *p
<< dendl
;
344 if (!pending_summary
.contains(p
->key())) {
345 pending_summary
.add(*p
);
346 pending_log
.insert(pair
<utime_t
,LogEntry
>(p
->stamp
, *p
));
349 pending_summary
.prune(g_conf
->mon_log_max_summary
);
350 wait_for_finished_proposal(op
, new C_Log(this, op
));
354 void LogMonitor::_updated_log(MonOpRequestRef op
)
356 MLog
*m
= static_cast<MLog
*>(op
->get_req());
357 dout(7) << "_updated_log for " << m
->get_orig_source_inst() << dendl
;
358 mon
->send_reply(op
, new MLogAck(m
->fsid
, m
->entries
.rbegin()->seq
));
361 bool LogMonitor::should_propose(double& delay
)
363 // commit now if we have a lot of pending events
364 if (g_conf
->mon_max_log_entries_per_event
> 0 &&
365 pending_log
.size() >= (unsigned)g_conf
->mon_max_log_entries_per_event
)
368 // otherwise fall back to generic policy
369 return PaxosService::should_propose(delay
);
373 bool LogMonitor::preprocess_command(MonOpRequestRef op
)
375 op
->mark_logmon_event("preprocess_command");
376 MMonCommand
*m
= static_cast<MMonCommand
*>(op
->get_req());
381 map
<string
, cmd_vartype
> cmdmap
;
382 if (!cmdmap_from_json(m
->cmd
, &cmdmap
, ss
)) {
383 string rs
= ss
.str();
384 mon
->reply_command(op
, -EINVAL
, rs
, get_last_committed());
387 MonSession
*session
= m
->get_session();
389 mon
->reply_command(op
, -EACCES
, "access denied", get_last_committed());
394 cmd_getval(g_ceph_context
, cmdmap
, "prefix", prefix
);
397 cmd_getval(g_ceph_context
, cmdmap
, "format", format
, string("plain"));
398 boost::scoped_ptr
<Formatter
> f(Formatter::create(format
));
400 if (prefix
== "log last") {
402 cmd_getval(g_ceph_context
, cmdmap
, "num", num
);
404 f
->open_array_section("tail");
406 auto p
= summary
.tail
.end();
407 while (num
> 0 && p
!= summary
.tail
.begin()) {
412 for ( ; p
!= summary
.tail
.end(); ++p
) {
414 f
->dump_object("entry", *p
);
423 rdata
.append(ss
.str());
432 mon
->reply_command(op
, r
, rs
, rdata
, get_last_committed());
437 bool LogMonitor::prepare_command(MonOpRequestRef op
)
439 op
->mark_logmon_event("prepare_command");
440 MMonCommand
*m
= static_cast<MMonCommand
*>(op
->get_req());
445 map
<string
, cmd_vartype
> cmdmap
;
446 if (!cmdmap_from_json(m
->cmd
, &cmdmap
, ss
)) {
447 // ss has reason for failure
448 string rs
= ss
.str();
449 mon
->reply_command(op
, -EINVAL
, rs
, get_last_committed());
454 cmd_getval(g_ceph_context
, cmdmap
, "prefix", prefix
);
456 MonSession
*session
= m
->get_session();
458 mon
->reply_command(op
, -EACCES
, "access denied", get_last_committed());
462 if (prefix
== "log") {
463 vector
<string
> logtext
;
464 cmd_getval(g_ceph_context
, cmdmap
, "logtext", logtext
);
466 le
.who
= m
->get_orig_source_inst();
467 le
.name
= session
->entity_name
;
468 le
.stamp
= m
->get_recv_stamp();
471 le
.msg
= str_join(logtext
, " ");
472 pending_summary
.add(le
);
473 pending_summary
.prune(g_conf
->mon_log_max_summary
);
474 pending_log
.insert(pair
<utime_t
,LogEntry
>(le
.stamp
, le
));
475 wait_for_finished_proposal(op
, new Monitor::C_Command(
476 mon
, op
, 0, string(), get_last_committed() + 1));
481 mon
->reply_command(op
, err
, rs
, get_last_committed());
486 int LogMonitor::sub_name_to_id(const string
& n
)
488 if (n
== "log-debug")
496 if (n
== "log-error")
501 void LogMonitor::check_subs()
503 dout(10) << __func__
<< dendl
;
504 for (map
<string
, xlist
<Subscription
*>*>::iterator i
= mon
->session_map
.subs
.begin();
505 i
!= mon
->session_map
.subs
.end();
507 for (xlist
<Subscription
*>::iterator j
= i
->second
->begin(); !j
.end(); ++j
) {
508 if (sub_name_to_id((*j
)->type
) >= 0)
514 void LogMonitor::check_sub(Subscription
*s
)
516 dout(10) << __func__
<< " client wants " << s
->type
<< " ver " << s
->next
<< dendl
;
518 int sub_level
= sub_name_to_id(s
->type
);
519 assert(sub_level
>= 0);
521 version_t summary_version
= summary
.version
;
522 if (s
->next
> summary_version
) {
523 dout(10) << __func__
<< " client " << s
->session
->inst
524 << " requested version (" << s
->next
<< ") is greater than ours ("
525 << summary_version
<< "), which means we already sent him"
526 << " everything we have." << dendl
;
530 MLog
*mlog
= new MLog(mon
->monmap
->fsid
);
533 /* First timer, heh? */
534 bool ret
= _create_sub_summary(mlog
, sub_level
);
536 dout(1) << __func__
<< " ret = " << ret
<< dendl
;
541 /* let us send you an incremental log... */
542 _create_sub_incremental(mlog
, sub_level
, s
->next
);
545 dout(1) << __func__
<< " sending message to " << s
->session
->inst
546 << " with " << mlog
->entries
.size() << " entries"
547 << " (version " << mlog
->version
<< ")" << dendl
;
549 if (!mlog
->entries
.empty()) {
550 s
->session
->con
->send_message(mlog
);
555 mon
->session_map
.remove_sub(s
);
557 s
->next
= summary_version
+1;
561 * Create a log message containing only the last message in the summary.
563 * @param mlog Log message we'll send to the client.
564 * @param level Maximum log level the client is interested in.
565 * @return 'true' if we consider we successfully populated @mlog;
568 bool LogMonitor::_create_sub_summary(MLog
*mlog
, int level
)
570 dout(10) << __func__
<< dendl
;
572 assert(mlog
!= NULL
);
574 if (!summary
.tail
.size())
577 list
<LogEntry
>::reverse_iterator it
= summary
.tail
.rbegin();
578 for (; it
!= summary
.tail
.rend(); ++it
) {
583 mlog
->entries
.push_back(e
);
584 mlog
->version
= summary
.version
;
592 * Create an incremental log message from version \p sv to \p summary.version
594 * @param mlog Log message we'll send to the client with the messages received
595 * since version \p sv, inclusive.
596 * @param level The max log level of the messages the client is interested in.
597 * @param sv The version the client is looking for.
599 void LogMonitor::_create_sub_incremental(MLog
*mlog
, int level
, version_t sv
)
601 dout(10) << __func__
<< " level " << level
<< " ver " << sv
602 << " cur summary ver " << summary
.version
<< dendl
;
604 if (sv
< get_first_committed()) {
605 dout(10) << __func__
<< " skipped from " << sv
606 << " to first_committed " << get_first_committed() << dendl
;
608 le
.stamp
= ceph_clock_now();
611 ss
<< "skipped log messages from " << sv
<< " to " << get_first_committed();
613 mlog
->entries
.push_back(le
);
614 sv
= get_first_committed();
617 version_t summary_ver
= summary
.version
;
618 while (sv
<= summary_ver
) {
620 int err
= get_version(sv
, bl
);
623 bufferlist::iterator p
= bl
.begin();
630 if (le
.prio
< level
) {
631 dout(20) << __func__
<< " requested " << level
632 << " entry " << le
.prio
<< dendl
;
636 mlog
->entries
.push_back(le
);
638 mlog
->version
= sv
++;
641 dout(10) << __func__
<< " incremental message ready ("
642 << mlog
->entries
.size() << " entries)" << dendl
;
645 void LogMonitor::update_log_channels()
651 int r
= get_conf_str_map_helper(g_conf
->mon_cluster_log_to_syslog
,
652 oss
, &channels
.log_to_syslog
,
653 CLOG_CONFIG_DEFAULT_KEY
);
655 derr
<< __func__
<< " error parsing 'mon_cluster_log_to_syslog'" << dendl
;
659 r
= get_conf_str_map_helper(g_conf
->mon_cluster_log_to_syslog_level
,
660 oss
, &channels
.syslog_level
,
661 CLOG_CONFIG_DEFAULT_KEY
);
663 derr
<< __func__
<< " error parsing 'mon_cluster_log_to_syslog_level'"
668 r
= get_conf_str_map_helper(g_conf
->mon_cluster_log_to_syslog_facility
,
669 oss
, &channels
.syslog_facility
,
670 CLOG_CONFIG_DEFAULT_KEY
);
672 derr
<< __func__
<< " error parsing 'mon_cluster_log_to_syslog_facility'"
677 r
= get_conf_str_map_helper(g_conf
->mon_cluster_log_file
, oss
,
679 CLOG_CONFIG_DEFAULT_KEY
);
681 derr
<< __func__
<< " error parsing 'mon_cluster_log_file'" << dendl
;
685 r
= get_conf_str_map_helper(g_conf
->mon_cluster_log_file_level
, oss
,
686 &channels
.log_file_level
,
687 CLOG_CONFIG_DEFAULT_KEY
);
689 derr
<< __func__
<< " error parsing 'mon_cluster_log_file_level'"
694 r
= get_conf_str_map_helper(g_conf
->mon_cluster_log_to_graylog
, oss
,
695 &channels
.log_to_graylog
,
696 CLOG_CONFIG_DEFAULT_KEY
);
698 derr
<< __func__
<< " error parsing 'mon_cluster_log_to_graylog'"
703 r
= get_conf_str_map_helper(g_conf
->mon_cluster_log_to_graylog_host
, oss
,
704 &channels
.log_to_graylog_host
,
705 CLOG_CONFIG_DEFAULT_KEY
);
707 derr
<< __func__
<< " error parsing 'mon_cluster_log_to_graylog_host'"
712 r
= get_conf_str_map_helper(g_conf
->mon_cluster_log_to_graylog_port
, oss
,
713 &channels
.log_to_graylog_port
,
714 CLOG_CONFIG_DEFAULT_KEY
);
716 derr
<< __func__
<< " error parsing 'mon_cluster_log_to_graylog_port'"
721 channels
.expand_channel_meta();
724 void LogMonitor::log_channel_info::expand_channel_meta(map
<string
,string
> &m
)
726 generic_dout(20) << __func__
<< " expand map: " << m
<< dendl
;
727 for (map
<string
,string
>::iterator p
= m
.begin(); p
!= m
.end(); ++p
) {
728 m
[p
->first
] = expand_channel_meta(p
->second
, p
->first
);
730 generic_dout(20) << __func__
<< " expanded map: " << m
<< dendl
;
733 string
LogMonitor::log_channel_info::expand_channel_meta(
735 const string
&change_to
)
737 size_t pos
= string::npos
;
739 while ((pos
= s
.find(LOG_META_CHANNEL
)) != string::npos
) {
740 string tmp
= s
.substr(0, pos
) + change_to
;
741 if (pos
+LOG_META_CHANNEL
.length() < s
.length())
742 tmp
+= s
.substr(pos
+LOG_META_CHANNEL
.length());
745 generic_dout(20) << __func__
<< " from '" << input
746 << "' to '" << s
<< "'" << dendl
;
751 bool LogMonitor::log_channel_info::do_log_to_syslog(const string
&channel
) {
752 string v
= get_str_map_key(log_to_syslog
, channel
,
753 &CLOG_CONFIG_DEFAULT_KEY
);
754 // We expect booleans, but they are in k/v pairs, kept
755 // as strings, in 'log_to_syslog'. We must ensure
756 // compatibility with existing boolean handling, and so
757 // we are here using a modified version of how
758 // md_config_t::set_val_raw() handles booleans. We will
759 // accept both 'true' and 'false', but will also check for
760 // '1' and '0'. The main distiction between this and the
761 // original code is that we will assume everything not '1',
762 // '0', 'true' or 'false' to be 'false'.
765 if (boost::iequals(v
, "false")) {
767 } else if (boost::iequals(v
, "true")) {
771 int b
= strict_strtol(v
.c_str(), 10, &err
);
772 ret
= (err
.empty() && b
== 1);
778 ceph::logging::Graylog::Ref
LogMonitor::log_channel_info::get_graylog(
779 const string
&channel
)
781 generic_dout(25) << __func__
<< " for channel '"
782 << channel
<< "'" << dendl
;
784 if (graylogs
.count(channel
) == 0) {
785 auto graylog(std::make_shared
<ceph::logging::Graylog
>("mon"));
787 graylog
->set_fsid(g_conf
->fsid
);
788 graylog
->set_hostname(g_conf
->host
);
789 graylog
->set_destination(get_str_map_key(log_to_graylog_host
, channel
,
790 &CLOG_CONFIG_DEFAULT_KEY
),
791 atoi(get_str_map_key(log_to_graylog_port
, channel
,
792 &CLOG_CONFIG_DEFAULT_KEY
).c_str()));
794 graylogs
[channel
] = graylog
;
795 generic_dout(20) << __func__
<< " for channel '"
796 << channel
<< "' to graylog host '"
797 << log_to_graylog_host
[channel
] << ":"
798 << log_to_graylog_port
[channel
]
801 return graylogs
[channel
];
804 void LogMonitor::handle_conf_change(const struct md_config_t
*conf
,
805 const std::set
<std::string
> &changed
)
807 if (changed
.count("mon_cluster_log_to_syslog") ||
808 changed
.count("mon_cluster_log_to_syslog_level") ||
809 changed
.count("mon_cluster_log_to_syslog_facility") ||
810 changed
.count("mon_cluster_log_file") ||
811 changed
.count("mon_cluster_log_file_level") ||
812 changed
.count("mon_cluster_log_to_graylog") ||
813 changed
.count("mon_cluster_log_to_graylog_host") ||
814 changed
.count("mon_cluster_log_to_graylog_port")) {
815 update_log_channels();