sopel/irc.py

#! /usr/bin/env python3
# -*- coding: utf-8 -*-
"""
Core IRC functionality. Support for Python 2 is largely gone.
"""
import sys
import os
import time
import socket
import codecs
import traceback
import threading
from datetime import datetime
import errno
import ssl
import asyncore
import asynchat

from logger import get_logger
from tools import stderr, Identifier
from trigger import PreTrigger

LOGGER = get_logger(__name__)


class Bot(asynchat.async_chat):
	def __init__(self, config):
		ca_certs = config.core.ca_certs

		asynchat.async_chat.__init__(self)
		self.set_terminator(b'\n')
		self.buffer = ''

		self.nick = Identifier(config.core.nick)
		"""Sopel's current ``Identifier``. Changing this while Sopel is running is
		untested."""
		self.user = config.core.user
		"""Sopel's user/ident."""
		self.name = config.core.name
		"""Sopel's "real name", as used for whois."""

		self.stack = {}
		self.ca_certs = ca_certs
		self.enabled_capabilities = set()
		self.hasquit = False

		self.sending = threading.RLock()
		self.writing_lock = threading.Lock()
		self.raw = None

		# We need this to prevent error loops in handle_error
		self.error_count = 0

		self.connection_registered = False
		""" Set to True when a server has accepted the client connection and
		messages can be sent and received. """

	def log_raw(self, line, prefix):
		"""Log raw line to the raw log."""
		if not self.config.core.log_raw:
			return
		if not os.path.isdir(self.config.core.logdir):
			try:
				os.mkdir(self.config.core.logdir)
			except Exception as e:
				stderr('There was a problem creating the logs directory.')
				stderr('%s %s' % (str(e.__class__), str(e)))
				stderr('Please fix this and then run Sopel again.')
				os._exit(1)
		f = codecs.open(os.path.join(self.config.core.logdir, 'raw.log'),
						'a', encoding='utf-8')
		f.write(prefix + str(time.time()) + "\t")
		temp = line.replace('\n', '')

		f.write(temp)
		f.write("\n")
		f.close()

	def safe(self, string):
		"""Remove newlines from a string."""
		if isinstance(string, bytes):
			string = string.decode('utf8')
		string = string.replace('\n', '')
		string = string.replace('\r', '')
		return string

	def write(self, args, text=None):
		args = [self.safe(arg) for arg in args]
		if text is not None:
			text = self.safe(text)
		try:
			self.writing_lock.acquire()  # Blocking lock, can't send two things
										 # at a time

			# From RFC2812 Internet Relay Chat: Client Protocol
			# Section 2.3
			#
			# https://tools.ietf.org/html/rfc2812.html
			#
			# IRC messages are always lines of characters terminated with a
			# CR-LF (Carriage Return - Line Feed) pair, and these messages SHALL
			# NOT exceed 512 characters in length, counting all characters
			# including the trailing CR-LF. Thus, there are 510 characters
			# maximum allowed for the command and its parameters.  There is no
			# provision for continuation of message lines.

			if text is not None:
				temp = (' '.join(args) + ' :' + text)[:510] + '\r\n'
			else:
				temp = ' '.join(args)[:510] + '\r\n'
			self.log_raw(temp, '>>')
			self.send(temp.encode('utf-8'))
		finally:
			self.writing_lock.release()

	def run(self, host, port=6667):
		try:
			self.initiate_connect(host, port)
		except socket.error as e:
			stderr('Connection error: %s' % e)

	def initiate_connect(self, host, port):
		stderr('Connecting to %s:%s...' % (host, port))
		source_address = ((self.config.core.bind_host, 0)
						  if self.config.core.bind_host else None)
		self.set_socket(socket.create_connection((host, port),
						source_address=source_address))
		if self.config.core.use_ssl:
			self.send = self._ssl_send
			self.recv = self._ssl_recv
		self.connect((host, port))
		try:
			asyncore.loop()
		except KeyboardInterrupt:
			print('KeyboardInterrupt')
			self.quit('KeyboardInterrupt')

	def quit(self, message):
		"""Disconnect from IRC and close the bot."""
		self.write(['QUIT'], message)
		self.hasquit = True
		# Wait for acknowledgement from the server. By RFC 2812 it should be
		# an ERROR msg, but many servers just close the connection. Either way
		# is fine by us.
		# Closing the connection now would mean that stuff in the buffers that
		# has not yet been processed would never be processed. It would also
		# release the main thread, which is problematic because whomever called
		# quit might still want to do something before main thread quits.

	def handle_close(self):
		self.connection_registered = False

		if hasattr(self, '_shutdown'):
			self._shutdown()
		stderr('Closed!')

		# This will eventually call asyncore dispatchers close method, which
		# will release the main thread. This should be called last to avoid
		# race conditions.
		self.close()

	def handle_connect(self):
		if self.config.core.use_ssl:
			if not self.config.core.verify_ssl:
				self.ssl = ssl.wrap_socket(self.socket,
										   do_handshake_on_connect=True,
										   suppress_ragged_eofs=True)
			else:
				self.ssl = ssl.wrap_socket(self.socket,
										   do_handshake_on_connect=True,
										   suppress_ragged_eofs=True,
										   cert_reqs=ssl.CERT_REQUIRED,
										   ca_certs=self.ca_certs)
				try:
					ssl.match_hostname(self.ssl.getpeercert(), self.config.core.host)
				except ssl.CertificateError:
					stderr("Invalid certficate, hostname mismatch!")
					os.unlink(self.config.core.pid_file_path)
					os._exit(1)
			self.set_socket(self.ssl)

		# Request list of server capabilities. IRCv3 servers will respond with
		# CAP * LS (which we handle in coretasks). v2 servers will respond with
		# 421 Unknown command, which we'll ignore
		self.write(('CAP', 'LS', '302'))

		if self.config.core.auth_method == 'server':
			password = self.config.core.auth_password
			self.write(('PASS', password))
		self.write(('NICK', self.nick))
		self.write(('USER', self.user, '+iw', self.nick), self.name)

		stderr('Connected.')
		self.last_ping_time = datetime.now()
		timeout_check_thread = threading.Thread(target=self._timeout_check)
		timeout_check_thread.daemon = True
		timeout_check_thread.start()
		ping_thread = threading.Thread(target=self._send_ping)
		ping_thread.daemon = True
		ping_thread.start()

	def _timeout_check(self):
		while self.connected or self.connecting:
			if (datetime.now() - self.last_ping_time).seconds > int(self.config.core.timeout):
				stderr('Ping timeout reached after %s seconds, closing connection' % self.config.core.timeout)
				self.handle_close()
				break
			else:
				time.sleep(int(self.config.core.timeout))

	def _send_ping(self):
		while self.connected or self.connecting:
			if self.connected and (datetime.now() - self.last_ping_time).seconds > int(self.config.core.timeout) / 2:
				try:
					self.write(('PING', self.config.core.host))
				except socket.error:
					pass
			time.sleep(int(self.config.core.timeout) / 2)

	def _ssl_send(self, data):
		"""Replacement for self.send() during SSL connections."""
		try:
			result = self.socket.send(data)
			return result
		except ssl.SSLError as why:
			if why[0] in (asyncore.EWOULDBLOCK, errno.ESRCH):
				return 0
			else:
				raise why
			return 0

	def _ssl_recv(self, buffer_size):
		"""Replacement for self.recv() during SSL connections.

		From: http://evanfosmark.com/2010/09/ssl-support-in-asynchatasync_chat

		"""
		try:
			data = self.socket.read(buffer_size)
			if not data:
				self.handle_close()
				return b''
			return data
		except ssl.SSLError as why:
			if why[0] in (asyncore.ECONNRESET, asyncore.ENOTCONN,
						  asyncore.ESHUTDOWN):
				self.handle_close()
				return ''
			elif why[0] == errno.ENOENT:
				# Required in order to keep it non-blocking
				return b''
			else:
				raise

	def collect_incoming_data(self, data):
		# We can't trust clients to pass valid str.
		try:
			data = str(data, encoding='utf-8')
		except strDecodeError:
			# not str, let's try cp1252
			try:
				data = str(data, encoding='cp1252')
			except strDecodeError:
				# Okay, let's try ISO8859-1
				try:
					data = str(data, encoding='iso8859-1')
				except:
					# Discard line if encoding is unknown
					return

		if data:
			self.log_raw(data, '<<')
		self.buffer += data

	def found_terminator(self):
		line = self.buffer
		if line.endswith('\r'):
			line = line[:-1]
		self.buffer = ''
		self.last_ping_time = datetime.now()
		pretrigger = PreTrigger(self.nick, line)
		if all(cap not in self.enabled_capabilities for cap in ['account-tag', 'extended-join']):
			pretrigger.tags.pop('account', None)

		if pretrigger.event == 'PING':
			self.write(('PONG', pretrigger.args[-1]))
		elif pretrigger.event == 'ERROR':
			LOGGER.error("ERROR recieved from server: %s", pretrigger.args[-1])
			if self.hasquit:
				self.close_when_done()
		elif pretrigger.event == '433':
			stderr('Nickname already in use!')
			self.handle_close()

		self.dispatch(pretrigger)

	def dispatch(self, pretrigger):
		pass

	def error(self, trigger=None):
		"""Called internally when a module causes an error."""
		try:
			trace = traceback.format_exc()
			if sys.version_info.major < 3:
				trace = trace.decode('utf-8', errors='xmlcharrefreplace')
			stderr(trace)
			try:
				lines = list(reversed(trace.splitlines()))
				report = [lines[0].strip()]
				for line in lines:
					line = line.strip()
					if line.startswith('File "'):
						report.append(line[0].lower() + line[1:])
						break
				else:
					report.append('source unknown')

				signature = '%s (%s)' % (report[0], report[1])
				# TODO: make not hardcoded
				log_filename = os.path.join(self.config.core.logdir, 'exceptions.log')
				with codecs.open(log_filename, 'a', encoding='utf-8') as logfile:
					logfile.write('Signature: %s\n' % signature)
					if trigger:
						logfile.write('from {} at {}. Message was: {}\n'.format(
							trigger.nick, str(datetime.now()), trigger.group(0)))
					logfile.write(trace)
					logfile.write(
						'----------------------------------------\n\n'
					)
			except Exception as e:
				stderr("Could not save full traceback!")
				LOGGER.error("Could not save traceback from %s to file: %s", trigger.sender, str(e))

			if trigger and self.config.core.reply_errors and trigger.sender is not None:
				self.say(signature, trigger.sender)
			if trigger:
				LOGGER.error('Exception from {}: {} ({})'.format(trigger.sender, str(signature), trigger.raw))
		except Exception as e:
			if trigger and self.config.core.reply_errors and trigger.sender is not None:
				self.say("Got an error.", trigger.sender)
			if trigger:
				LOGGER.error('Exception from {}: {} ({})'.format(trigger.sender, str(e), trigger.raw))

	def handle_error(self):
		"""Handle any uncaptured error in the core.

		Overrides asyncore's handle_error.

		"""
		trace = traceback.format_exc()
		stderr(trace)
		LOGGER.error('Fatal error in core, please review exception log')
		# TODO: make not hardcoded
		logfile = codecs.open(
			os.path.join(self.config.core.logdir, 'exceptions.log'),
			'a',
			encoding='utf-8'
		)
		logfile.write('Fatal error in core, handle_error() was called\n')
		logfile.write('last raw line was %s' % self.raw)
		logfile.write(trace)
		logfile.write('Buffer:\n')
		logfile.write(self.buffer)
		logfile.write('----------------------------------------\n\n')
		logfile.close()
		if self.error_count > 10:
			if (datetime.now() - self.last_error_timestamp).seconds < 5:
				stderr("Too many errors, can't continue")
				os._exit(1)
		self.last_error_timestamp = datetime.now()
		self.error_count = self.error_count + 1