Skip to content
Snippets Groups Projects
Commit b6cdc473 authored by Rob Swindell's avatar Rob Swindell :speech_balloon:
Browse files

Log message improvements: include protocol (HTTP vs HTTPS) and IP address

parent e672b5c9
No related branches found
No related tags found
1 merge request!463MRC mods by Codefenix (2024-10-20)
Pipeline #3206 passed
Stage: build
Show whitespace changes
Inline Side-by-side
Showing
with 40 additions and 32 deletions
src/sbbs3/websrvr.c
+ 40
− 32
View file @ b6cdc473
...@@ -1239,8 +1239,8 @@ static BOOL send_headers(http_session_t *session, const char *status, int chunke ...@@ -1239,8 +1239,8 @@ static BOOL send_headers(http_session_t *session, const char *status, int chunke
session->req.sent_headers=TRUE; session->req.sent_headers=TRUE;
return(FALSE); return(FALSE);
} }
lprintf(LOG_DEBUG,"%04d Request resolved to: %s" lprintf(LOG_DEBUG,"%04d %s [%s] Request resolved to: %s"
,session->socket,session->req.physical_path); ,session->socket, session->client.protocol, session->host_ip, session->req.physical_path);
if(session->http_ver <= HTTP_0_9) { if(session->http_ver <= HTTP_0_9) {
session->req.sent_headers=TRUE; session->req.sent_headers=TRUE;
if(session->req.ld != NULL) if(session->req.ld != NULL)
...@@ -1312,7 +1312,7 @@ static BOOL send_headers(http_session_t *session, const char *status, int chunke ...@@ -1312,7 +1312,7 @@ static BOOL send_headers(http_session_t *session, const char *status, int chunke
/* Status-Line */ /* Status-Line */
safe_snprintf(header,sizeof(header),"%s %s",response_http_vers[session->http_ver > HTTP_0_9 ? HTTP_1_1 : HTTP_0_9],status_line); safe_snprintf(header,sizeof(header),"%s %s",response_http_vers[session->http_ver > HTTP_0_9 ? HTTP_1_1 : HTTP_0_9],status_line);
lprintf(LOG_DEBUG,"%04d Result: %s",session->socket,header); lprintf(LOG_DEBUG,"%04d %s [%s] Result: %s", session->socket, session->client.protocol, session->host_ip, header);
safecat(headers,header,MAX_HEADERS_SIZE); safecat(headers,header,MAX_HEADERS_SIZE);
...@@ -1447,7 +1447,7 @@ static off_t sock_sendfile(http_session_t *session,char *path, off_t start, off_ ...@@ -1447,7 +1447,7 @@ static off_t sock_sendfile(http_session_t *session,char *path, off_t start, off_
uint64_t remain; uint64_t remain;
if(startup->options&WEB_OPT_DEBUG_TX) if(startup->options&WEB_OPT_DEBUG_TX)
lprintf(LOG_DEBUG,"%04d Sending %s",session->socket,path); lprintf(LOG_DEBUG,"%04d %s [%s] Sending %s",session->socket, session->client.protocol, session->host_ip, path);
if((file=open(path,O_RDONLY|O_BINARY))==-1) if((file=open(path,O_RDONLY|O_BINARY))==-1)
lprintf(LOG_WARNING,"%04d !ERROR %d opening %s",session->socket,errno,path); lprintf(LOG_WARNING,"%04d !ERROR %d opening %s",session->socket,errno,path);
else { else {
...@@ -1491,7 +1491,8 @@ static void send_error(http_session_t * session, unsigned line, const char* mess ...@@ -1491,7 +1491,8 @@ static void send_error(http_session_t * session, unsigned line, const char* mess
if(session->socket==INVALID_SOCKET) if(session->socket==INVALID_SOCKET)
return; return;
session->req.if_modified_since=0; session->req.if_modified_since=0;
lprintf(LOG_INFO,"%04d [%s] !ERROR: %s (line %u)",session->socket,session->host_ip,message,line); lprintf(LOG_INFO,"%04d %s [%s] !ERROR: %s (line %u) request: %s"
,session->socket, session->client.protocol, session->host_ip, message, line, session->req.request_line);
session->req.keep_alive=FALSE; session->req.keep_alive=FALSE;
session->req.send_location=NO_LOCATION; session->req.send_location=NO_LOCATION;
SAFECOPY(error_code,message); SAFECOPY(error_code,message);
...@@ -1587,7 +1588,8 @@ void http_logon(http_session_t * session, user_t *usr) ...@@ -1587,7 +1588,8 @@ void http_logon(http_session_t * session, user_t *usr)
if(session->user.number==session->last_user_num) if(session->user.number==session->last_user_num)
return; return;
lprintf(LOG_DEBUG,"%04d HTTP Logon (user #%d)",session->socket,session->user.number); lprintf(LOG_DEBUG,"%04d %s [%s] Logon (user #%d)"
,session->socket, session->client.protocol, session->host_ip, session->user.number);
if(session->subscan!=NULL) if(session->subscan!=NULL)
getmsgptrs(&scfg,&session->user,session->subscan,NULL,NULL); getmsgptrs(&scfg,&session->user,session->subscan,NULL,NULL);
...@@ -1616,8 +1618,8 @@ void http_logoff(http_session_t* session, SOCKET socket, int line) ...@@ -1616,8 +1618,8 @@ void http_logoff(http_session_t* session, SOCKET socket, int line)
if(session->last_user_num<=0) if(session->last_user_num<=0)
return; return;
lprintf(LOG_DEBUG,"%04d HTTP Logoff (user #%d) from line %d" lprintf(LOG_DEBUG,"%04d %s [%s] Logoff (user #%d) from line %d"
,socket,session->user.number, line); ,socket, session->client.protocol, session->host_ip, session->user.number, line);
SAFECOPY(session->username,unknown); SAFECOPY(session->username,unknown);
if(!logoutuserdat(&scfg, &session->user, time(NULL), session->logon_time)) if(!logoutuserdat(&scfg, &session->user, time(NULL), session->logon_time))
...@@ -2040,8 +2042,8 @@ static BOOL check_ars(http_session_t * session) ...@@ -2040,8 +2042,8 @@ static BOOL check_ars(http_session_t * session)
} }
/* Should go to the hack log? */ /* Should go to the hack log? */
lprintf(LOG_WARNING,"%04d !AUTHORIZATION FAILURE for user %s, ARS: %s" lprintf(LOG_WARNING,"%04d %s [%s] !AUTHORIZATION FAILURE for user %s, ARS: %s"
,session->socket,session->req.auth.username,session->req.ars); ,session->socket, session->client.protocol, session->host_ip, session->req.auth.username, session->req.ars);
#ifdef _WIN32 #ifdef _WIN32
if(startup->sound.hack[0] && !sound_muted(&scfg)) if(startup->sound.hack[0] && !sound_muted(&scfg))
...@@ -2314,7 +2316,8 @@ static void js_add_queryval(http_session_t * session, char *key, char *value) ...@@ -2314,7 +2316,8 @@ static void js_add_queryval(http_session_t * session, char *key, char *value)
alen=len; alen=len;
} }
lprintf(LOG_DEBUG,"%04d Adding query value %s=%s at pos %d",session->socket,key,value,alen); lprintf(LOG_DEBUG,"%04d %s [%s] Adding query value %s=%s at pos %d"
,session->socket, session->client.protocol, session->host_ip, key,value,alen);
val=STRING_TO_JSVAL(JS_NewStringCopyZ(session->js_cx,value)); val=STRING_TO_JSVAL(JS_NewStringCopyZ(session->js_cx,value));
JS_SetElement(session->js_cx, keyarray, alen, &val); JS_SetElement(session->js_cx, keyarray, alen, &val);
} }
...@@ -2345,7 +2348,8 @@ static void js_add_cookieval(http_session_t * session, char *key, char *value) ...@@ -2345,7 +2348,8 @@ static void js_add_cookieval(http_session_t * session, char *key, char *value)
alen=len; alen=len;
} }
lprintf(LOG_DEBUG,"%04d Adding cookie value %s=%s at pos %d",session->socket,key,value,alen); lprintf(LOG_DEBUG,"%04d %s [%s] Adding cookie value %s=%s at pos %d"
,session->socket, session->client.protocol, session->host_ip, key,value,alen);
val=STRING_TO_JSVAL(JS_NewStringCopyZ(session->js_cx,value)); val=STRING_TO_JSVAL(JS_NewStringCopyZ(session->js_cx,value));
JS_SetElement(session->js_cx, keyarray, alen, &val); JS_SetElement(session->js_cx, keyarray, alen, &val);
} }
...@@ -3267,13 +3271,13 @@ static BOOL get_req(http_session_t * session, char *request_line) ...@@ -3267,13 +3271,13 @@ static BOOL get_req(http_session_t * session, char *request_line)
if(len<0) if(len<0)
return(FALSE); return(FALSE);
if(req_line[0]) if(req_line[0])
lprintf(LOG_INFO,"%04d Request: %s",session->socket,req_line); lprintf(LOG_INFO,"%04d %s [%s] Request: %s",session->socket, session->client.protocol, session->host_ip, req_line);
if(session->req.ld!=NULL && session->req.ld->request==NULL) if(session->req.ld!=NULL && session->req.ld->request==NULL)
/* FREE()d in http_logging_thread() */ /* FREE()d in http_logging_thread() */
session->req.ld->request=strdup(req_line); session->req.ld->request=strdup(req_line);
} }
else { else {
lprintf(LOG_DEBUG,"%04d Handling Internal Redirect to: %s",session->socket,request_line); lprintf(LOG_DEBUG,"%04d %s [%s] Handling Internal Redirect to: %s",session->socket, session->client.protocol, session->host_ip, request_line);
session->req.extra_path_info[0]=0; session->req.extra_path_info[0]=0;
SAFECOPY(req_line,request_line); SAFECOPY(req_line,request_line);
is_redir=1; is_redir=1;
...@@ -3493,7 +3497,7 @@ static BOOL exec_js_webctrl(http_session_t* session, char *name, char* script, c ...@@ -3493,7 +3497,7 @@ static BOOL exec_js_webctrl(http_session_t* session, char *name, char* script, c
session->js_callback.counter=0; session->js_callback.counter=0;
lprintf(LOG_DEBUG,"%04d JavaScript: Compiling %s", session->socket, name); lprintf(LOG_DEBUG,"%04d %s [%s] JavaScript: Compiling %s", session->socket, session->client.protocol, session->host_ip, name);
if(!JS_EvaluateScript(session->js_cx, session->js_glob, script, strlen(script), name, 1, &rval)) { if(!JS_EvaluateScript(session->js_cx, session->js_glob, script, strlen(script), name, 1, &rval)) {
lprintf(LOG_WARNING,"%04d !JavaScript FAILED to compile rewrite %s:%s" lprintf(LOG_WARNING,"%04d !JavaScript FAILED to compile rewrite %s:%s"
,session->socket,name,script); ,session->socket,name,script);
...@@ -3611,7 +3615,7 @@ static BOOL check_request(http_session_t * session) ...@@ -3611,7 +3615,7 @@ static BOOL check_request(http_session_t * session)
SAFECOPY(path,session->req.physical_path); SAFECOPY(path,session->req.physical_path);
if(startup->options&WEB_OPT_DEBUG_TX) if(startup->options&WEB_OPT_DEBUG_TX)
lprintf(LOG_DEBUG,"%04d Path is: %s",session->socket,path); lprintf(LOG_DEBUG,"%04d %s [%s] Path is: %s",session->socket, session->client.protocol, session->host_ip, path);
if(isdir(path)) { if(isdir(path)) {
last_ch=*lastchar(path); last_ch=*lastchar(path);
if(!IS_PATH_DELIM(last_ch)) { if(!IS_PATH_DELIM(last_ch)) {
...@@ -3668,7 +3672,7 @@ static BOOL check_request(http_session_t * session) ...@@ -3668,7 +3672,7 @@ static BOOL check_request(http_session_t * session)
session->req.keep_alive=FALSE; session->req.keep_alive=FALSE;
send_error(session,__LINE__,"400 Bad Request"); send_error(session,__LINE__,"400 Bad Request");
SAFEPRINTF2(str, "Request for '%s' is outside of web root: %s", path, root_dir); SAFEPRINTF2(str, "Request for '%s' is outside of web root: %s", path, root_dir);
lprintf(LOG_NOTICE,"%04d !ERROR %s", session->socket, str); lprintf(LOG_NOTICE,"%04d %s [%s] !ERROR %s", session->socket, session->client.protocol, session->host_ip, str);
hacklog(&scfg, session->client.protocol, session->username, str, session->client.host, &session->addr); hacklog(&scfg, session->client.protocol, session->username, str, session->client.host, &session->addr);
#ifdef _WIN32 #ifdef _WIN32
if(startup->sound.hack[0] && !sound_muted(&scfg)) if(startup->sound.hack[0] && !sound_muted(&scfg))
...@@ -4682,7 +4686,7 @@ static BOOL exec_fastcgi(http_session_t *session) ...@@ -4682,7 +4686,7 @@ static BOOL exec_fastcgi(http_session_t *session)
.arg = &cd .arg = &cd
}; };
lprintf(LOG_INFO,"%04d Executing FastCGI: %s",session->socket,session->req.physical_path); lprintf(LOG_INFO,"%04d %s [%s] Executing FastCGI: %s",session->socket, session->client.protocol, session->host_ip, session->req.physical_path);
if (session->req.fastcgi_socket == NULL) { if (session->req.fastcgi_socket == NULL) {
lprintf(LOG_ERR, "%04d No FastCGI socket configured!",session->socket); lprintf(LOG_ERR, "%04d No FastCGI socket configured!",session->socket);
return FALSE; return FALSE;
...@@ -4787,7 +4791,7 @@ static BOOL exec_cgi(http_session_t *session) ...@@ -4787,7 +4791,7 @@ static BOOL exec_cgi(http_session_t *session)
SAFECOPY(cmdline,session->req.physical_path); SAFECOPY(cmdline,session->req.physical_path);
lprintf(LOG_INFO,"%04d Executing CGI: %s",session->socket,cmdline); lprintf(LOG_INFO,"%04d %s [%s] Executing CGI: %s",session->socket, session->client.protocol, session->host_ip, cmdline);
orig_keep=session->req.keep_alive; orig_keep=session->req.keep_alive;
session->req.keep_alive=FALSE; session->req.keep_alive=FALSE;
...@@ -4936,8 +4940,8 @@ static BOOL exec_cgi(http_session_t *session) ...@@ -4936,8 +4940,8 @@ static BOOL exec_cgi(http_session_t *session)
done_wait = (waitpid(child,&status,WNOHANG)==child); done_wait = (waitpid(child,&status,WNOHANG)==child);
if(!done_wait) { if(!done_wait) {
if(start) if(start)
lprintf(LOG_NOTICE,"%04d CGI Process %s still alive on client exit" lprintf(LOG_NOTICE,"%04d %s [%s] CGI Process %s still alive on client exit"
,session->socket,getfname(cmdline)); ,session->socket, session->client.protocol, session->host_ip, getfname(cmdline));
kill(child,SIGTERM); kill(child,SIGTERM);
mswait(1000); mswait(1000);
done_wait = (waitpid(child,&status,WNOHANG)==child); done_wait = (waitpid(child,&status,WNOHANG)==child);
...@@ -4955,7 +4959,7 @@ static BOOL exec_cgi(http_session_t *session) ...@@ -4955,7 +4959,7 @@ static BOOL exec_cgi(http_session_t *session)
i=read(err_pipe[0],buf,sizeof(buf)-1); i=read(err_pipe[0],buf,sizeof(buf)-1);
if(i!=-1 && i!=0) { if(i!=-1 && i!=0) {
buf[i]=0; buf[i]=0;
lprintf(LOG_ERR,"%04d CGI Error: %s",session->socket,buf); lprintf(LOG_ERR,"%04d %s [%s] !CGI Error: %s",session->socket, session->client.protocol, session->host_ip, buf);
} }
} }
...@@ -6496,7 +6500,8 @@ void http_session_thread(void* arg) ...@@ -6496,7 +6500,8 @@ void http_session_thread(void* arg)
thread_down(); thread_down();
return; return;
} }
lprintf(LOG_DEBUG,"%04d Session thread started", session.socket); session.client.protocol=session.is_tls ? "HTTPS":"HTTP";
lprintf(LOG_DEBUG,"%04d %s [%s] Session thread started", session.socket, session.client.protocol, session.host_ip);
if(startup->index_file_name==NULL || startup->cgi_ext==NULL) if(startup->index_file_name==NULL || startup->cgi_ext==NULL)
lprintf(LOG_DEBUG,"%04d !!! DANGER WILL ROBINSON, DANGER !!!", session.socket); lprintf(LOG_DEBUG,"%04d !!! DANGER WILL ROBINSON, DANGER !!!", session.socket);
...@@ -6568,7 +6573,8 @@ void http_session_thread(void* arg) ...@@ -6568,7 +6573,8 @@ void http_session_thread(void* arg)
char host_name[128] = ""; char host_name[128] = "";
if(!(startup->options&BBS_OPT_NO_HOST_LOOKUP)) { if(!(startup->options&BBS_OPT_NO_HOST_LOOKUP)) {
getnameinfo(&session.addr.addr, session.addr_len, host_name, sizeof(host_name), NULL, 0, NI_NAMEREQD); getnameinfo(&session.addr.addr, session.addr_len, host_name, sizeof(host_name), NULL, 0, NI_NAMEREQD);
lprintf(LOG_INFO,"%04d Hostname: %s [%s]", session.socket, host_name[0] ? host_name : STR_NO_HOSTNAME, session.host_ip); lprintf(LOG_INFO,"%04d %s [%s] Hostname: %s"
,session.socket, session.client.protocol, session.host_ip, host_name[0] ? host_name : STR_NO_HOSTNAME);
#if 0 /* gethostbyaddr() is apparently not (always) thread-safe #if 0 /* gethostbyaddr() is apparently not (always) thread-safe
and getnameinfo() doesn't return alias information */ and getnameinfo() doesn't return alias information */
for(i=0;host!=NULL && host->h_aliases!=NULL for(i=0;host!=NULL && host->h_aliases!=NULL
...@@ -6576,7 +6582,8 @@ void http_session_thread(void* arg) ...@@ -6576,7 +6582,8 @@ void http_session_thread(void* arg)
lprintf(LOG_INFO,"%04d HostAlias: %s", session.socket, host->h_aliases[i]); lprintf(LOG_INFO,"%04d HostAlias: %s", session.socket, host->h_aliases[i]);
#endif #endif
if(host_name[0] && trashcan(&scfg, host_name,"host")) { if(host_name[0] && trashcan(&scfg, host_name,"host")) {
lprintf(LOG_NOTICE,"%04d !CLIENT BLOCKED in host.can: %s", session.socket, host_name); lprintf(LOG_NOTICE,"%04d %s [%s] !CLIENT BLOCKED in host.can: %s"
,session.socket, session.client.protocol, session.host_ip, host_name);
close_session_socket(&session); close_session_socket(&session);
sem_wait(&session.output_thread_terminated); sem_wait(&session.output_thread_terminated);
sem_destroy(&session.output_thread_terminated); sem_destroy(&session.output_thread_terminated);
...@@ -6599,10 +6606,11 @@ void http_session_thread(void* arg) ...@@ -6599,10 +6606,11 @@ void http_session_thread(void* arg)
if(banned || trashcan(&scfg,session.host_ip,"ip")) { if(banned || trashcan(&scfg,session.host_ip,"ip")) {
if(banned) { if(banned) {
char ban_duration[128]; char ban_duration[128];
lprintf(LOG_NOTICE, "%04d !TEMPORARY BAN of %s (%lu login attempts, last: %s) - remaining: %s" lprintf(LOG_NOTICE, "%04d %s !TEMPORARY BAN of %s (%lu login attempts, last: %s) - remaining: %s"
,session.socket, session.host_ip, attempted.count-attempted.dupes, attempted.user, seconds_to_str(banned, ban_duration)); ,session.socket, session.client.protocol
,session.host_ip, attempted.count-attempted.dupes, attempted.user, seconds_to_str(banned, ban_duration));
} else } else
lprintf(LOG_NOTICE, "%04d !CLIENT BLOCKED in ip.can: %s", session.socket, session.host_ip); lprintf(LOG_NOTICE, "%04d %s !CLIENT BLOCKED in ip.can: %s", session.socket, session.client.protocol, session.host_ip);
close_session_socket(&session); close_session_socket(&session);
sem_wait(&session.output_thread_terminated); sem_wait(&session.output_thread_terminated);
sem_destroy(&session.output_thread_terminated); sem_destroy(&session.output_thread_terminated);
...@@ -6619,7 +6627,6 @@ void http_session_thread(void* arg) ...@@ -6619,7 +6627,6 @@ void http_session_thread(void* arg)
SAFECOPY(session.client.host, host_name); SAFECOPY(session.client.host, host_name);
session.client.port=inet_addrport(&session.addr); session.client.port=inet_addrport(&session.addr);
session.client.time=time32(NULL); session.client.time=time32(NULL);
session.client.protocol=session.is_tls ? "HTTPS":"HTTP";
session.client.user=session.username; session.client.user=session.username;
session.client.size=sizeof(session.client); session.client.size=sizeof(session.client);
session.client.usernum = 0; session.client.usernum = 0;
...@@ -6708,7 +6715,8 @@ void http_session_thread(void* arg) ...@@ -6708,7 +6715,8 @@ void http_session_thread(void* arg)
safe_snprintf(session.redir_req,sizeof(session.redir_req),"%s %s%s%s",methods[session.req.method] safe_snprintf(session.redir_req,sizeof(session.redir_req),"%s %s%s%s",methods[session.req.method]
,session.req.virtual_path,session.http_ver<HTTP_1_0?"":" ",http_vers[session.http_ver]); ,session.req.virtual_path,session.http_ver<HTTP_1_0?"":" ",http_vers[session.http_ver]);
} }
lprintf(LOG_DEBUG,"%04d Internal Redirect to: %s",socket,session.redir_req); lprintf(LOG_DEBUG,"%04d %s [%s] Internal Redirect to: %s"
,socket, session.client.protocol, session.host_ip, session.redir_req);
redirp=session.redir_req; redirp=session.redir_req;
} }
} }
...@@ -6759,8 +6767,8 @@ void http_session_thread(void* arg) ...@@ -6759,8 +6767,8 @@ void http_session_thread(void* arg)
if(startup->index_file_name==NULL || startup->cgi_ext==NULL) if(startup->index_file_name==NULL || startup->cgi_ext==NULL)
lprintf(LOG_DEBUG,"%04d !!! ALL YOUR BASE ARE BELONG TO US !!!", socket); lprintf(LOG_DEBUG,"%04d !!! ALL YOUR BASE ARE BELONG TO US !!!", socket);
lprintf(LOG_INFO,"%04d Session thread terminated (%u clients, %u threads remain, %lu served)" lprintf(LOG_INFO,"%04d %s [%s] Session thread terminated (%u clients, %u threads remain, %lu served)"
,socket, clients_remain, protected_uint32_value(thread_count), served); ,socket, session.client.protocol, session.host_ip, clients_remain, protected_uint32_value(thread_count), served);
} }
......
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Please register or to comment