From 0d8ebf58453d0dff446d363250631994e75f1fe5 Mon Sep 17 00:00:00 2001 From: Carlos Esquerdo Bernat Date: Wed, 22 Jul 2020 16:31:22 +0200 Subject: [PATCH] websocket: use log instead submodule logger (1/4) (#5921) --- vlib/net/websocket/events.v | 8 +-- vlib/net/websocket/handshake.v | 27 ++++---- vlib/net/websocket/io.v | 7 +- vlib/net/websocket/logger/logger.v | 56 ---------------- vlib/net/websocket/ssl.v | 10 +-- vlib/net/websocket/utf8.v | 3 +- vlib/net/websocket/utils.v | 4 +- vlib/net/websocket/ws.v | 104 +++++++++++++++-------------- 8 files changed, 82 insertions(+), 137 deletions(-) delete mode 100644 vlib/net/websocket/logger/logger.v diff --git a/vlib/net/websocket/events.v b/vlib/net/websocket/events.v index 08cc0700aa..12ae3295c4 100644 --- a/vlib/net/websocket/events.v +++ b/vlib/net/websocket/events.v @@ -2,20 +2,20 @@ module websocket fn (ws &Client) send_message_event(msg &Message) { ws.eb.publish('on_message', ws, msg) - l.d('sending on_message event') + ws.log.debug('sending on_message event') } fn (ws &Client) send_error_event(err string) { ws.eb.publish('on_error', ws, err) - l.d('sending on_error event') + ws.log.debug('sending on_error event') } fn (ws &Client) send_close_event() { ws.eb.publish('on_close', ws, voidptr(0)) - l.d('sending on_close event') + ws.log.debug('sending on_close event') } fn (ws &Client) send_open_event() { ws.eb.publish('on_open', ws, voidptr(0)) - l.d('sending on_open event') + ws.log.debug('sending on_open event') } diff --git a/vlib/net/websocket/handshake.v b/vlib/net/websocket/handshake.v index 1e3770abb2..97589a97c9 100644 --- a/vlib/net/websocket/handshake.v +++ b/vlib/net/websocket/handshake.v @@ -1,7 +1,7 @@ module websocket fn (mut ws Client) read_handshake(seckey string) { - l.d('reading handshake...') + ws.log.debug('reading handshake...') mut bytes_read := 0 max_buffer := 1024 buffer_size := 1 @@ -12,10 +12,11 @@ fn (mut ws Client) read_handshake(seckey string) { res = ws.read_from_server(buffer + bytes_read, buffer_size) } if res == 0 || res == -1 { - l.f('read_handshake: Failed to read handshake.') + ws.log.fatal('read_handshake: Failed to read handshake.') } - if buffer[bytes_read] == `\n` && buffer[bytes_read - 1] == `\r` && buffer[bytes_read - - 2] == `\n` && buffer[bytes_read - 3] == `\r` { + if buffer[bytes_read] == `\n` && + buffer[bytes_read - 1] == `\r` && buffer[bytes_read - 2] == `\n` && + buffer[bytes_read - 3] == `\r` { break } bytes_read += buffer_size @@ -25,11 +26,11 @@ fn (mut ws Client) read_handshake(seckey string) { } fn (mut ws Client) handshake_handler(handshake_response, seckey string) { - l.d('handshake_handler:\r\n${handshake_response}') + ws.log.debug('handshake_handler:\r\n$handshake_response') lines := handshake_response.split_into_lines() header := lines[0] if !header.starts_with('HTTP/1.1 101') && !header.starts_with('HTTP/1.0 101') { - l.f('handshake_handler: invalid HTTP status response code') + ws.log.fatal('handshake_handler: invalid HTTP status response code') } for i in 1 .. lines.len { if lines[i].len <= 0 || lines[i] == '\r\n' { @@ -44,13 +45,13 @@ fn (mut ws Client) handshake_handler(handshake_response, seckey string) { ws.flags << .has_connection } 'Sec-WebSocket-Accept', 'sec-websocket-accept' { - l.d('comparing hashes') - l.d('seckey: ${seckey}') + ws.log.debug('comparing hashes') + ws.log.debug('seckey: $seckey') challenge := create_key_challenge_response(seckey) - l.d('challenge: ${challenge}') - l.d('response: ${keys[1]}') + ws.log.debug('challenge: $challenge') + ws.log.debug('response: ${keys[1]}') if keys[1].trim_space() != challenge { - l.e('handshake_handler: Sec-WebSocket-Accept header does not match computed sha1/base64 response.') + ws.log.error('handshake_handler: Sec-WebSocket-Accept header does not match computed sha1/base64 response.') } ws.flags << .has_accept unsafe { @@ -65,9 +66,9 @@ fn (mut ws Client) handshake_handler(handshake_response, seckey string) { } if ws.flags.len < 3 { ws.close(1002, 'invalid websocket HTTP headers') - l.e('invalid websocket HTTP headers') + ws.log.error('invalid websocket HTTP headers') } - l.i('handshake successful!') + ws.log.info('handshake successful!') unsafe { handshake_response.free() lines.free() diff --git a/vlib/net/websocket/io.v b/vlib/net/websocket/io.v index 0666fd0b20..dfe31059a5 100644 --- a/vlib/net/websocket/io.v +++ b/vlib/net/websocket/io.v @@ -3,11 +3,8 @@ module websocket fn (mut ws Client) write_to_server(buf voidptr, len int) int { mut bytes_written := 0 ws.write_lock.m_lock() - bytes_written = if ws.is_ssl { - C.SSL_write(ws.ssl, buf, len) - } else { - C.write(ws.socket.sockfd, buf, len) - } + bytes_written = if ws.is_ssl { C.SSL_write(ws.ssl, buf, len) } else { C.write(ws.socket.sockfd, + buf, len) } ws.write_lock.unlock() return bytes_written } diff --git a/vlib/net/websocket/logger/logger.v b/vlib/net/websocket/logger/logger.v deleted file mode 100644 index db053e8948..0000000000 --- a/vlib/net/websocket/logger/logger.v +++ /dev/null @@ -1,56 +0,0 @@ -module logger - -const ( - colors = { - "success": "\e[32", - "debug": "\e[36", - "error": "\e[91", - "warn": "\e[33", - "critical": "\e[31", - "fatal": "\e[31", - "info": "\e[37" - } -) - -struct Logger { - mod string -} - -pub fn new(mod string) &Logger { - return &Logger{mod: mod} -} - -pub fn (l &Logger) d(message string){ - $if debug { - l.print("debug", message) - } -} - -pub fn (l &Logger) i(message string){ - l.print('info', message) -} - -pub fn (l &Logger) e(message string){ - l.print('error', message) -} - -pub fn (l &Logger) c(message string){ - l.print('critical', message) -} - -pub fn (l &Logger) f(message string){ - l.print('fatal', message) - exit(-1) -} - -pub fn (l &Logger) w(message string){ - l.print('warn', message) -} - -pub fn (l &Logger) s(message string) { - l.print('success', message) -} - -fn (l &Logger) print(mod, message string) { - println('${colors[mod]};7m[${mod}]\e[0m \e[1m${l.mod}\e[0m: ${message}') -} diff --git a/vlib/net/websocket/ssl.v b/vlib/net/websocket/ssl.v index 83df1e9cb4..ea3e7aec27 100644 --- a/vlib/net/websocket/ssl.v +++ b/vlib/net/websocket/ssl.v @@ -7,20 +7,20 @@ const ( ) fn (mut ws Client) connect_ssl() { - l.i('Using secure SSL connection') + ws.log.info('Using secure SSL connection') C.SSL_load_error_strings() ws.sslctx = C.SSL_CTX_new(C.SSLv23_client_method()) if ws.sslctx == 0 { - l.f("Couldn't get ssl context") + ws.log.fatal("Couldn't get ssl context") } ws.ssl = C.SSL_new(ws.sslctx) if ws.ssl == 0 { - l.f("Couldn't create OpenSSL instance.") + ws.log.fatal("Couldn't create OpenSSL instance.") } if C.SSL_set_fd(ws.ssl, ws.socket.sockfd) != 1 { - l.f("Couldn't assign ssl to socket.") + ws.log.fatal("Couldn't assign ssl to socket.") } if C.SSL_connect(ws.ssl) != 1 { - l.f("Couldn't connect using SSL.") + ws.log.fatal("Couldn't connect using SSL.") } } diff --git a/vlib/net/websocket/utf8.v b/vlib/net/websocket/utf8.v index f35a1e8381..18e2f1eab8 100644 --- a/vlib/net/websocket/utf8.v +++ b/vlib/net/websocket/utf8.v @@ -28,8 +28,7 @@ pub fn utf8_validate(data byteptr, len int) bool { } fn (mut s Utf8State) seq(r0, r1, is_tail bool) bool { - if s.subindex == 0 || (s.index > 1 && s.subindex == 1) || (s.index >= 6 && s.subindex == - 2) { + if s.subindex == 0 || (s.index > 1 && s.subindex == 1) || (s.index >= 6 && s.subindex == 2) { if (s.subindex == 0 && r0) || (s.subindex == 1 && r1) || (s.subindex == 2 && is_tail) { s.subindex++ return true diff --git a/vlib/net/websocket/utils.v b/vlib/net/websocket/utils.v index b201961a71..d2c1ffe5a4 100644 --- a/vlib/net/websocket/utils.v +++ b/vlib/net/websocket/utils.v @@ -20,7 +20,9 @@ fn htonl64(payload_len u64) byteptr { fn create_masking_key() []byte { mask_bit := byte(rand.intn(255)) buf := [`0`].repeat(4) - unsafe { C.memcpy(buf.data, &mask_bit, 4) } + unsafe { + C.memcpy(buf.data, &mask_bit, 4) + } return buf } diff --git a/vlib/net/websocket/ws.v b/vlib/net/websocket/ws.v index f595156d11..673489a84b 100644 --- a/vlib/net/websocket/ws.v +++ b/vlib/net/websocket/ws.v @@ -5,20 +5,16 @@ import net.urllib import encoding.base64 import eventbus import sync -import net.websocket.logger - -const ( - l = logger.new('ws') -) +import log pub struct Client { retry int eb &eventbus.EventBus is_ssl bool +mut: // subprotocol_len int // cwebsocket_subprotocol *subprotocol; // cwebsocket_subprotocol *subprotocols[]; -mut: mtx &sync.Mutex = sync.new_mutex() write_lock &sync.Mutex = sync.new_mutex() state State @@ -28,6 +24,9 @@ mut: ssl &C.SSL fragments []Fragment pub mut: + log log.Log = log.Log{ + output_label: 'ws' +} uri string subscriber &eventbus.Subscriber nonce_size int = 18 // you can try 16 too @@ -120,13 +119,13 @@ fn (ws &Client) parse_uri() &Uri { pub fn (mut ws Client) connect() int { match ws.state { .connected { - l.f('connect: websocket already connected') + ws.log.fatal('connect: websocket already connected') } .connecting { - l.f('connect: websocket already connecting') + ws.log.fatal('connect: websocket already connecting') } .open { - l.f('connect: websocket already open') + ws.log.fatal('connect: websocket already open') } else { // do nothing @@ -140,21 +139,21 @@ pub fn (mut ws Client) connect() int { seckey := base64.encode(nonce) ai_family := C.AF_INET ai_socktype := C.SOCK_STREAM - l.d('handshake header:') - handshake := 'GET ${uri.resource}${uri.querystring} HTTP/1.1\r\nHost: ${uri.hostname}:${uri.port}\r\nUpgrade: websocket\r\nConnection: Upgrade\r\nSec-WebSocket-Key: ${seckey}\r\nSec-WebSocket-Version: 13\r\n\r\n' - l.d(handshake) + ws.log.debug('handshake header:') + handshake := 'GET $uri.resource$uri.querystring HTTP/1.1\r\nHost: $uri.hostname:$uri.port\r\nUpgrade: websocket\r\nConnection: Upgrade\r\nSec-WebSocket-Key: $seckey\r\nSec-WebSocket-Version: 13\r\n\r\n' + ws.log.debug(handshake) socket := net.new_socket(ai_family, ai_socktype, 0) or { - l.f(err) + ws.log.fatal(err) return -1 } ws.socket = socket ws.socket.connect(uri.hostname, uri.port.int()) or { - l.f(err) + ws.log.fatal(err) return -1 } optval := 1 ws.socket.setsockopt(C.SOL_SOCKET, C.SO_KEEPALIVE, &optval) or { - l.f(err) + ws.log.fatal(err) return -1 } if ws.is_ssl { @@ -165,7 +164,7 @@ pub fn (mut ws Client) connect() int { ws.mtx.unlock() res := ws.write_to_server(handshake.str, handshake.len) if res <= 0 { - l.f('Handshake failed.') + ws.log.fatal('Handshake failed.') } ws.read_handshake(seckey) ws.mtx.m_lock() @@ -208,7 +207,7 @@ pub fn (mut ws Client) close(code int, message string) { } } else { if C.shutdown(ws.socket.sockfd, C.SHUT_WR) == -1 { - l.e('Unabled to shutdown websocket.') + ws.log.error('Unabled to shutdown websocket.') } mut buf := [`0`] for ws.read_from_server(buf.data, 1) > 0 { @@ -226,8 +225,6 @@ pub fn (mut ws Client) close(code int, message string) { ws.mtx.m_lock() ws.state = .closed ws.mtx.unlock() - unsafe { - } // TODO impl autoreconnect } } @@ -244,7 +241,7 @@ pub fn (mut ws Client) write(payload byteptr, payload_len int, code OPCode) int header_len := 6 + if payload_len > 125 { 2 } else { 0 } + if payload_len > 0xffff { 6 } else { 0 } frame_len := header_len + payload_len mut frame_buf := [`0`].repeat(frame_len) - fbdata := byteptr( frame_buf.data ) + fbdata := byteptr(frame_buf.data) masking_key := create_masking_key() mut header := [`0`].repeat(header_len) header[0] = byte(code) | 0x80 @@ -275,13 +272,12 @@ pub fn (mut ws Client) write(payload byteptr, payload_len int, code OPCode) int header[12] = masking_key[2] header[13] = masking_key[3] } else { - l.c('write: frame too large') + ws.log.fatal('write: frame too large') ws.close(1009, 'frame too large') goto free_data return -1 } - unsafe - { + unsafe { C.memcpy(fbdata, header.data, header_len) C.memcpy(fbdata + header_len, payload, payload_len) } @@ -291,12 +287,12 @@ pub fn (mut ws Client) write(payload byteptr, payload_len int, code OPCode) int bytes_written = ws.write_to_server(fbdata, frame_len) if bytes_written == -1 { err := string(byteptr(C.strerror(C.errno))) - l.e('write: there was an error writing data: ${err}') + ws.log.error('write: there was an error writing data: $err') ws.send_error_event('Error writing data') goto free_data return -1 } - l.d('write: ${bytes_written} bytes written.') + ws.log.debug('write: $bytes_written bytes written.') free_data: unsafe { free(payload) @@ -308,11 +304,11 @@ pub fn (mut ws Client) write(payload byteptr, payload_len int, code OPCode) int } pub fn (mut ws Client) listen() { - l.i('Starting listener...') + ws.log.info('Starting listener...') for ws.state == .open { ws.read() } - l.i('Listener stopped as websocket was closed.') + ws.log.info('Listener stopped as websocket was closed.') } pub fn (mut ws Client) read() int { @@ -334,7 +330,7 @@ pub fn (mut ws Client) read() int { match byt { 0 { error := 'server closed the connection.' - l.e('read: ${error}') + ws.log.error('read: $error') ws.send_error_event(error) ws.close(1006, error) goto free_data @@ -342,7 +338,7 @@ pub fn (mut ws Client) read() int { } -1 { err := string(byteptr(C.strerror(C.errno))) - l.e('read: error reading frame. ${err}') + ws.log.error('read: error reading frame. $err') ws.send_error_event('error reading frame') goto free_data return -1 @@ -384,7 +380,7 @@ pub fn (mut ws Client) read() int { payload_len = u64(extended_payload_len) frame_size = u64(header_len) + payload_len if frame_size > initial_buffer { - l.d('reallocating: ${frame_size}') + ws.log.debug('reallocating: $frame_size') data = v_realloc(data, u32(frame_size)) } } else if frame.payload_len == u64(127) && bytes_read == u64(extended_payload64_end_byte) { @@ -408,7 +404,7 @@ pub fn (mut ws Client) read() int { payload_len = extended_payload_len frame_size = u64(header_len) + payload_len if frame_size > initial_buffer { - l.d('reallocating: ${frame_size}') + ws.log.debug('reallocating: $frame_size') data = v_realloc(data, u32(frame_size)) // TODO u64 => u32 } } @@ -425,12 +421,14 @@ pub fn (mut ws Client) read() int { return -1 } else if frame.opcode in [.text_frame, .binary_frame] { data_node: - l.d('read: recieved text_frame or binary_frame') + ws.log.debug('read: recieved text_frame or binary_frame') mut payload := malloc(int(sizeof(byte) * u32(payload_len) + 1)) if payload == 0 { - l.f('out of memory') + ws.log.fatal('out of memory') + } + unsafe { + C.memcpy(payload, &data[header_len], payload_len) } - unsafe { C.memcpy(payload, &data[header_len], payload_len) } if frame.fin { if ws.fragments.len > 0 { // join fragments @@ -448,7 +446,7 @@ pub fn (mut ws Client) read() int { } mut pl := malloc(int(sizeof(byte) * u32(size))) if pl == 0 { - l.f('out of memory') + ws.log.fatal('out of memory') } mut by := 0 for f in frags { @@ -472,7 +470,7 @@ pub fn (mut ws Client) read() int { payload[payload_len] = `\0` if frame.opcode == .text_frame && payload_len > 0 { if !utf8_validate(payload, int(payload_len)) { - l.e('malformed utf8 payload') + ws.log.error('malformed utf8 payload') ws.send_error_event('Recieved malformed utf8.') ws.close(1007, 'malformed utf8 payload') goto free_data @@ -498,9 +496,9 @@ pub fn (mut ws Client) read() int { } return int(bytes_read) } else if frame.opcode == .continuation { - l.d('read: continuation') + ws.log.debug('read: continuation') if ws.fragments.len <= 0 { - l.e('Nothing to continue.') + ws.log.error('Nothing to continue.') ws.close(1002, 'nothing to continue') goto free_data return -1 @@ -508,7 +506,7 @@ pub fn (mut ws Client) read() int { goto data_node return 0 } else if frame.opcode == .ping { - l.d('read: ping') + ws.log.debug('read: ping') if !frame.fin { ws.close(1002, 'control message must not be fragmented') goto free_data @@ -522,7 +520,9 @@ pub fn (mut ws Client) read() int { mut payload := []byte{} if payload_len > 0 { payload = [`0`].repeat(int(payload_len)) - unsafe { C.memcpy(payload.data, &data[header_len], payload_len) } + unsafe { + C.memcpy(payload.data, &data[header_len], payload_len) + } } unsafe { free(data) @@ -540,7 +540,7 @@ pub fn (mut ws Client) read() int { // got pong return 0 } else if frame.opcode == .close { - l.d('read: close') + ws.log.debug('read: close') if frame.payload_len > 125 { ws.close(1002, 'control frames must not exceed 125 bytes') goto free_data @@ -553,9 +553,9 @@ pub fn (mut ws Client) read() int { header_len += 2 payload_len -= 2 reason = string(&data[header_len]) - l.i('Closing with reason: ${reason} & code: ${code}') + ws.log.info('Closing with reason: $reason & code: $code') if reason.len > 1 && !utf8_validate(reason.str, reason.len) { - l.e('malformed utf8 payload') + ws.log.error('malformed utf8 payload') ws.send_error_event('Recieved malformed utf8.') ws.close(1007, 'malformed utf8 payload') goto free_data @@ -568,8 +568,8 @@ pub fn (mut ws Client) read() int { ws.close(code, reason) return 0 } - l.e('read: Recieved unsupported opcode: ${frame.opcode} fin: ${frame.fin} uri: ${ws.uri}') - ws.send_error_event('Recieved unsupported opcode: ${frame.opcode}') + ws.log.error('read: Recieved unsupported opcode: $frame.opcode fin: $frame.fin uri: $ws.uri') + ws.send_error_event('Recieved unsupported opcode: $frame.opcode') ws.close(1002, 'Unsupported opcode') free_data: unsafe { @@ -581,11 +581,11 @@ pub fn (mut ws Client) read() int { fn (mut ws Client) send_control_frame(code OPCode, frame_typ string, payload []byte) int { mut bytes_written := -1 if ws.socket.sockfd <= 0 { - l.e('No socket opened.') + ws.log.error('No socket opened.') unsafe { payload.free() } - l.c('send_control_frame: error sending ${frame_typ} control frame.') + ws.log.fatal('send_control_frame: error sending $frame_typ control frame.') return -1 } header_len := 6 @@ -601,7 +601,9 @@ fn (mut ws Client) send_control_frame(code OPCode, frame_typ string, payload []b if code == .close { if payload.len > 2 { mut parsed_payload := [`0`].repeat(payload.len + 1) - unsafe { C.memcpy(parsed_payload.data, &payload[0], payload.len) } + unsafe { + C.memcpy(parsed_payload.data, &payload[0], payload.len) + } parsed_payload[payload.len] = `\0` for i in 0 .. payload.len { control_frame[6 + i] = (parsed_payload[i] ^ masking_key[i % 4]) & 0xff @@ -624,15 +626,15 @@ fn (mut ws Client) send_control_frame(code OPCode, frame_typ string, payload []b } match bytes_written { 0 { - l.d('send_control_frame: remote host closed the connection.') + ws.log.debug('send_control_frame: remote host closed the connection.') return 0 } -1 { - l.c('send_control_frame: error sending ${frame_typ} control frame.') + ws.log.error('send_control_frame: error sending $frame_typ control frame.') return -1 } else { - l.d('send_control_frame: wrote ${bytes_written} byte ${frame_typ} frame.') + ws.log.debug('send_control_frame: wrote $bytes_written byte $frame_typ frame.') return bytes_written } }