Browse Source

logging and debugging

pull/8210/head
Chris Lu 2 days ago
parent
commit
000e2bd4a9
  1. 22
      unmaintained/local-nginx/nginx.conf
  2. 2
      weed/admin/dash/worker_grpc_server.go
  3. 2
      weed/admin/maintenance/maintenance_queue.go
  4. 1
      weed/s3api/s3api_bucket_handlers.go
  5. 2
      weed/s3api/s3api_object_handlers_list.go
  6. 1
      weed/s3api/s3api_object_versioning.go
  7. 12
      weed/worker/client.go
  8. 12
      weed/worker/worker.go

22
unmaintained/local-nginx/nginx.conf

@ -12,14 +12,25 @@ http {
sendfile on; sendfile on;
keepalive_timeout 65; keepalive_timeout 65;
log_format debug '$remote_addr - $remote_user [$time_local] '
'"$request" $status $body_bytes_sent '
'request_body: "$request_body" '
'upstream_status: "$upstream_status" '
'upstream_response_time: "$upstream_response_time" '
'resp_content_type: "$sent_http_content_type" '
'resp_content_length: "$sent_http_content_length"';
access_log logs/access.log debug;
error_log logs/error.log debug;
# Standard Configuration from Wiki # Standard Configuration from Wiki
upstream seaweedfs { upstream seaweedfs {
server 127.0.0.1:8334;
server 127.0.0.1:8333;
keepalive 20; keepalive 20;
} }
server { server {
listen 8333 ssl;
listen 443 ssl;
server_name localhost; server_name localhost;
ssl_certificate cert.pem; ssl_certificate cert.pem;
@ -33,6 +44,7 @@ http {
ignore_invalid_headers off; ignore_invalid_headers off;
client_max_body_size 0; client_max_body_size 0;
client_body_buffer_size 128k;
proxy_buffering off; proxy_buffering off;
location / { location / {
@ -48,8 +60,12 @@ http {
proxy_connect_timeout 300; proxy_connect_timeout 300;
proxy_http_version 1.1; proxy_http_version 1.1;
proxy_set_header Connection ""; proxy_set_header Connection "";
proxy_request_buffering off;
proxy_request_buffering on;
chunked_transfer_encoding off; chunked_transfer_encoding off;
# Log response headers
add_header X-Debug-Status $upstream_status;
add_header X-Debug-Time $upstream_response_time;
} }
} }
} }

2
weed/admin/dash/worker_grpc_server.go

@ -418,7 +418,7 @@ func (s *WorkerGrpcServer) handleTaskRequest(conn *WorkerConnection, request *wo
select { select {
case conn.outgoing <- noTaskAssignment: case conn.outgoing <- noTaskAssignment:
glog.V(2).Infof("Sent 'No Task' response to worker %s", conn.workerID)
glog.V(4).Infof("Sent 'No Task' response to worker %s", conn.workerID)
case <-time.After(time.Second): case <-time.After(time.Second):
// If we can't send, the worker will eventually time out and reconnect, which is fine // If we can't send, the worker will eventually time out and reconnect, which is fine
} }

2
weed/admin/maintenance/maintenance_queue.go

@ -272,7 +272,7 @@ func (mq *MaintenanceQueue) GetNextTask(workerID string, capabilities []Maintena
// If no task found, return nil // If no task found, return nil
if selectedTask == nil { if selectedTask == nil {
glog.V(2).Infof("No suitable tasks available for worker %s (checked %d pending tasks)", workerID, len(mq.pendingTasks))
glog.V(4).Infof("No suitable tasks available for worker %s (checked %d pending tasks)", workerID, len(mq.pendingTasks))
return nil return nil
} }

1
weed/s3api/s3api_bucket_handlers.go

@ -117,6 +117,7 @@ func (s3a *S3ApiServer) ListBucketsHandler(w http.ResponseWriter, r *http.Reques
Buckets: listBuckets, Buckets: listBuckets,
} }
glog.V(3).Infof("ListBucketsHandler response: %+v", response)
writeSuccessResponseXML(w, r, response) writeSuccessResponseXML(w, r, response)
} }

2
weed/s3api/s3api_object_handlers_list.go

@ -109,6 +109,7 @@ func (s3a *S3ApiServer) ListObjectsV2Handler(w http.ResponseWriter, r *http.Requ
responseV2.EncodingType = s3.EncodingTypeUrl responseV2.EncodingType = s3.EncodingTypeUrl
} }
glog.V(3).Infof("ListObjectsV2Handler response: %+v", responseV2)
writeSuccessResponseXML(w, r, responseV2) writeSuccessResponseXML(w, r, responseV2)
} }
@ -155,6 +156,7 @@ func (s3a *S3ApiServer) ListObjectsV1Handler(w http.ResponseWriter, r *http.Requ
} }
} }
glog.V(3).Infof("ListObjectsV1Handler response: %+v", response)
writeSuccessResponseXML(w, r, response) writeSuccessResponseXML(w, r, response)
} }

1
weed/s3api/s3api_object_versioning.go

@ -1094,6 +1094,7 @@ func (s3a *S3ApiServer) ListObjectVersionsHandler(w http.ResponseWriter, r *http
// Set the original prefix in the response (not the normalized internal prefix) // Set the original prefix in the response (not the normalized internal prefix)
result.Prefix = originalPrefix result.Prefix = originalPrefix
glog.V(3).Infof("ListObjectVersionsHandler response: %+v", result)
writeSuccessResponseXML(w, r, result) writeSuccessResponseXML(w, r, result)
} }

12
weed/worker/client.go

@ -524,7 +524,7 @@ func handleIncoming(
// Route message to general handler. // Route message to general handler.
select { select {
case incoming <- msg: case incoming <- msg:
glog.V(3).Infof("[session %s] Message routed to incoming channel", sessionID)
glog.V(4).Infof("[session %s] Message routed to incoming channel", sessionID)
case <-time.After(time.Second): case <-time.After(time.Second):
glog.Warningf("[session %s] Incoming message buffer full, dropping message: %T", sessionID, msg.Message) glog.Warningf("[session %s] Incoming message buffer full, dropping message: %T", sessionID, msg.Message)
} }
@ -825,21 +825,21 @@ func (c *GrpcAdminClient) RequestTask(workerID string, capabilities []types.Task
select { select {
case c.outgoing <- msg: case c.outgoing <- msg:
glog.V(3).Infof("TASK REQUEST SENT: Worker %s successfully sent task request to admin server", workerID)
glog.V(4).Infof("TASK REQUEST SENT: Worker %s successfully sent task request to admin server", workerID)
case <-time.After(time.Second): case <-time.After(time.Second):
glog.Errorf("TASK REQUEST TIMEOUT: Worker %s failed to send task request: timeout", workerID) glog.Errorf("TASK REQUEST TIMEOUT: Worker %s failed to send task request: timeout", workerID)
return nil, fmt.Errorf("failed to send task request: timeout") return nil, fmt.Errorf("failed to send task request: timeout")
} }
// Wait for task assignment // Wait for task assignment
glog.V(3).Infof("WAITING FOR RESPONSE: Worker %s waiting for task assignment response (30s timeout)", workerID)
glog.V(4).Infof("WAITING FOR RESPONSE: Worker %s waiting for task assignment response (30s timeout)", workerID)
timeout := time.NewTimer(30 * time.Second) timeout := time.NewTimer(30 * time.Second)
defer timeout.Stop() defer timeout.Stop()
for { for {
select { select {
case response := <-c.incoming: case response := <-c.incoming:
glog.V(3).Infof("RESPONSE RECEIVED: Worker %s received response from admin server: %T", workerID, response.Message)
glog.V(4).Infof("RESPONSE RECEIVED: Worker %s received response from admin server: %T", workerID, response.Message)
if taskAssign := response.GetTaskAssignment(); taskAssign != nil { if taskAssign := response.GetTaskAssignment(); taskAssign != nil {
// Validate TaskId is not empty before processing // Validate TaskId is not empty before processing
if taskAssign.TaskId == "" { if taskAssign.TaskId == "" {
@ -865,10 +865,10 @@ func (c *GrpcAdminClient) RequestTask(workerID string, capabilities []types.Task
} }
return task, nil return task, nil
} else { } else {
glog.V(3).Infof("NON-TASK RESPONSE: Worker %s received non-task response: %T", workerID, response.Message)
glog.V(4).Infof("NON-TASK RESPONSE: Worker %s received non-task response: %T", workerID, response.Message)
} }
case <-timeout.C: case <-timeout.C:
glog.V(3).Infof("TASK REQUEST TIMEOUT: Worker %s - no task assignment received within 30 seconds", workerID)
glog.V(4).Infof("TASK REQUEST TIMEOUT: Worker %s - no task assignment received within 30 seconds", workerID)
return nil, nil // No task available return nil, nil // No task available
} }
} }

12
weed/worker/worker.go

@ -799,7 +799,7 @@ func (w *Worker) requestTasks() {
} }
if w.getAdmin() != nil { if w.getAdmin() != nil {
glog.V(3).Infof("REQUESTING TASK: Worker %s requesting task from admin server (current load: %d/%d, capabilities: %v)",
glog.V(4).Infof("REQUESTING TASK: Worker %s requesting task from admin server (current load: %d/%d, capabilities: %v)",
w.id, currentLoad, w.config.MaxConcurrent, w.config.Capabilities) w.id, currentLoad, w.config.MaxConcurrent, w.config.Capabilities)
task, err := w.getAdmin().RequestTask(w.id, w.config.Capabilities) task, err := w.getAdmin().RequestTask(w.id, w.config.Capabilities)
@ -815,7 +815,7 @@ func (w *Worker) requestTasks() {
glog.Errorf("TASK HANDLING FAILED: Worker %s failed to handle task %s: %v", w.id, task.ID, err) glog.Errorf("TASK HANDLING FAILED: Worker %s failed to handle task %s: %v", w.id, task.ID, err)
} }
} else { } else {
glog.V(3).Infof("NO TASK AVAILABLE: Worker %s - admin server has no tasks available", w.id)
glog.V(4).Infof("NO TASK AVAILABLE: Worker %s - admin server has no tasks available", w.id)
} }
} }
} }
@ -868,7 +868,7 @@ func (w *Worker) connectionMonitorLoop() {
lastConnectionStatus = currentConnectionStatus lastConnectionStatus = currentConnectionStatus
} else { } else {
if currentConnectionStatus { if currentConnectionStatus {
glog.V(3).Infof("CONNECTION OK: Worker %s connection status: connected", w.id)
glog.V(4).Infof("CONNECTION OK: Worker %s connection status: connected", w.id)
} else { } else {
glog.V(1).Infof("CONNECTION DOWN: Worker %s connection status: disconnected, reconnection in progress", w.id) glog.V(1).Infof("CONNECTION DOWN: Worker %s connection status: disconnected, reconnection in progress", w.id)
} }
@ -926,10 +926,10 @@ func (w *Worker) messageProcessingLoop() {
return return
case message := <-incomingChan: case message := <-incomingChan:
if message != nil { if message != nil {
glog.V(3).Infof("MESSAGE PROCESSING: Worker %s processing incoming message", w.id)
glog.V(4).Infof("MESSAGE PROCESSING: Worker %s processing incoming message", w.id)
w.processAdminMessage(message) w.processAdminMessage(message)
} else { } else {
glog.V(3).Infof("NULL MESSAGE: Worker %s received nil message", w.id)
glog.V(4).Infof("NULL MESSAGE: Worker %s received nil message", w.id)
} }
} }
} }
@ -952,7 +952,7 @@ func (w *Worker) processAdminMessage(message *worker_pb.AdminMessage) {
case *worker_pb.AdminMessage_TaskAssignment: case *worker_pb.AdminMessage_TaskAssignment:
taskAssign := msg.TaskAssignment taskAssign := msg.TaskAssignment
if taskAssign.TaskId == "" { if taskAssign.TaskId == "" {
glog.V(1).Infof("Worker %s received empty task assignment, going to sleep", w.id)
glog.V(4).Infof("Worker %s received empty task assignment, going to sleep", w.id)
return return
} }
glog.V(1).Infof("Worker %s received direct task assignment %s (type: %s, volume: %d)", glog.V(1).Infof("Worker %s received direct task assignment %s (type: %s, volume: %d)",

Loading…
Cancel
Save