logging http responses

4 files changed, 56 insertions, 15 deletions

diff --git a/rotord/rendercontext.cpp b/rotord/rendercontext.cpp
index 776e842..7362d64 100644
--- a/rotord/rendercontext.cpp
+++ b/rotord/rendercontext.cpp
@@ -50,6 +50,7 @@ void Render_context::add_queue(int item) {
 	mutex.unlock();
 }
 void Render_context::session_command(const std::vector<std::string>& command,xmlIO& XML,HTTPResponse::HTTPStatus& status){
+	Logger& logger = Logger::get("Rotor");
 	status=HTTPResponse::HTTP_BAD_REQUEST; //error by default
 	if (command[2]=="resolution") {
 		if (command[0]=="PUT") {
@@ -60,10 +61,12 @@ void Render_context::session_command(const std::vector<std::string>& command,xml
 						int w=ofToInt(t1[0]);
 						int h=ofToInt(t1[1]);
 						if (graph.set_resolution(w,h)){
+							logger.information("resolution set to "+t1[0]+"x"+t1[1]);
 							XML.addValue("status","resolution set to "+t1[0]+"x"+t1[1]);
 							status=HTTPResponse::HTTP_OK;
 						}
 						else {
+							logger.error("ERROR: invalid resolution request: "+t1[0]+"x"+t1[1]);
 							XML.addValue("error","invalid resolution request: "+t1[0]+"x"+t1[1]);
 						}
 					}
@@ -84,15 +87,18 @@ void Render_context::session_command(const std::vector<std::string>& command,xml
 															//pass to worker thread ??if engine is ready?? ??what if engine has finished but results aren't read??
 					    add_queue(ANALYSE_AUDIO);
 					    status=HTTPResponse::HTTP_OK;
+					    logger.information("Starting audio analysis: "+command[3]);
 					    XML.addValue("status","Starting audio analysis: "+command[3]);
 					}
 					else {
 					    status=HTTPResponse::HTTP_NOT_FOUND;
+					    logger.error("ERROR: audio file "+command[3]+" not found");
 					    XML.addValue("error",command[3]+" not found");
 					}
 
 			    }
 			    else {
+			    	logger.error("ERROR: Session busy");
 					XML.addValue("error","Session busy");
 				}
 			}
@@ -114,16 +120,19 @@ void Render_context::session_command(const std::vector<std::string>& command,xml
 				XML.addValue("audio",audio_thumb->print());
 			}
 			else {
+				logger.error("ERROR: audio thumbnail requested but no audio loaded");
 				XML.addValue("error","No audio loaded");
 			}
 	     }
 	     if (command[0]=="DELETE") {
 		    if (state==IDLE) {
 				audio_filename="";
+				logger.information("Audio deleted");
 				XML.addValue("status","Audio deleted");
 				status=HTTPResponse::HTTP_OK;
 			}
 			else {
+				logger.error("ERROR: Session busy");
 				XML.addValue("error","Session busy");
 			}
 	     }
@@ -133,9 +142,11 @@ void Render_context::session_command(const std::vector<std::string>& command,xml
 			if (graph.loaded) {
 				status=HTTPResponse::HTTP_OK;
 				//XML.addValue("patchbay",graph.toString());
+				logger.information("Requested graph");
 				XML.loadFromBuffer(graph.toString());
 			}
 			else {
+				logger.error("ERROR: graph not loaded: check XML");
 				XML.addValue("error","graph not loaded: check XML");
 			}
 		}
@@ -146,10 +157,12 @@ void Render_context::session_command(const std::vector<std::string>& command,xml
 				if (state==IDLE) {					//eventually not like this
 					if (graph.load(command[3])) {
 						status=HTTPResponse::HTTP_OK;
+						logger.information("Loaded graph from http PUT body");
 						XML.addValue("status","Loaded graph from PUT body");
 						if (audio_loaded) {
 							add_queue(ANALYSE_AUDIO);
 						    status=HTTPResponse::HTTP_OK;
+						    logger.information("Starting audio analysis for graph: "+command[3]);
 						    XML.addValue("status","Starting audio analysis for graph: "+command[3]);
 						}
 					}
@@ -169,16 +182,19 @@ void Render_context::session_command(const std::vector<std::string>& command,xml
 								if (audio_loaded) {
 									add_queue(ANALYSE_AUDIO);
 								    status=HTTPResponse::HTTP_OK;
+								    logger.information("Starting audio analysis for graph: "+command[3]);
 								    XML.addValue("status","Starting audio analysis for graph: "+command[3]);
 								}
 							}
 							else {
 								status=HTTPResponse::HTTP_INTERNAL_SERVER_ERROR; //~/sources/poco-1.4.6-all/Net/include/Poco/Net/HTTPResponse.h
+								logger.error("ERROR: graph not loaded: check XML");
 								XML.addValue("error","graph not loaded: check XML");
 							}
 						}
 						else {
 						    status=HTTPResponse::HTTP_NOT_FOUND;
+						    logger.error("ERROR: "+command[3]+" not found");
 						    XML.addValue("error",command[3]+" not found");
 						}
 					}
@@ -188,6 +204,7 @@ void Render_context::session_command(const std::vector<std::string>& command,xml
 		if (command[0]=="DELETE") {
 			 //for now
 			graph=Graph();
+			logger.information("graph deleted");
 			XML.addValue("status","graph deleted");
 			status=HTTPResponse::HTTP_OK;
 		}
@@ -203,10 +220,12 @@ void Render_context::session_command(const std::vector<std::string>& command,xml
 					string signal_xml;
 					if (graph.signal_render(signal_xml,framerate)){
 						status=HTTPResponse::HTTP_OK;
-						XML.addValue("signal",signal_xml); //this doesn't work
+						logger.information("rendering signal to xml");
+						XML.addValue("signal",signal_xml); //this doesn't work >> pseudo xml 
 					}
 					else {
 						status=HTTPResponse::HTTP_INTERNAL_SERVER_ERROR;
+						logger.error("ERROR: could not render output signal");
 						XML.addValue("error","could not render output signal");
 					}
 					//else {
@@ -216,6 +235,7 @@ void Render_context::session_command(const std::vector<std::string>& command,xml
 			}
 			else {
 				status=HTTPResponse::HTTP_SERVICE_UNAVAILABLE;
+				logger.error("ERROR: context busy");
 				XML.addValue("error","Context busy");
 			}
 		}
@@ -232,25 +252,30 @@ void Render_context::session_command(const std::vector<std::string>& command,xml
 																	//pass to worker thread ??if engine is ready?? ??what if engine has finished but results aren't read??
 																	//DUMMY RESPONSE
 							status=HTTPResponse::HTTP_OK;
+							logger.information("Succesfully loaded "+command[4]+" into video node "+command[3]);
 							XML.addValue("status","Succesfully loaded "+command[4]+" into video node "+command[3]);
 						}
 						else {
 							status=HTTPResponse::HTTP_INTERNAL_SERVER_ERROR;
+							logger.error("ERROR: could not load "+command[4]+" into video node "+command[3]);
 							XML.addValue("error","could not load "+command[4]+" into video node "+command[3]);
 						}
 					}
 					else {
 					    status=HTTPResponse::HTTP_NOT_FOUND;
-					    XML.addValue("error",command[4]+" not found");
+					    logger.error("ERROR: "+command[4]+" not found");
+						XML.addValue("error",command[4]+" not found");
 					}
 			    }
 			    else {
 					status=HTTPResponse::HTTP_BAD_REQUEST;
+					logger.error("ERROR: Session busy");
 					XML.addValue("error","Session busy");
 			    }
 			}
 			else {
 				status=HTTPResponse::HTTP_BAD_REQUEST;
+				logger.error("ERROR: Bad request");
 				XML.addValue("error","Bad request");
 			}
 		}
@@ -263,6 +288,7 @@ void Render_context::session_command(const std::vector<std::string>& command,xml
 				XML.addValue("progress",ofToString(progress));
 			}
 			else {
+				logger.error("ERROR: Render progress requested but not rendering");
 				XML.addValue("error","Not rendering");
 			}
 		}
@@ -275,28 +301,32 @@ void Render_context::session_command(const std::vector<std::string>& command,xml
 						}
 					    add_queue(RENDER);
 					    status=HTTPResponse::HTTP_OK;
-					    XML.addValue("status","Starting render: "+command[3]);
+					    logger.information("Starting render: "+command[3]);
+						XML.addValue("status","Starting render: "+command[3]);
 			    }
 			    else {
 					status=HTTPResponse::HTTP_BAD_REQUEST;
+					logger.error("ERROR: Session busy");
 					XML.addValue("error","Session busy");
 		    	}
 			}
 			else {
 				status=HTTPResponse::HTTP_BAD_REQUEST;
+				logger.error("ERROR: No output file specified");
 				XML.addValue("error","No output file specified");
 		    }
 		}
 		if (command[0]=="DELETE") {
 			status=HTTPResponse::HTTP_OK;
+			logger.error("ERROR: Not implemented");
 			XML.addValue("status","DUMMY RESPONSE: cancelling render");
 		}
 	}
 }
 
 bool Render_context::load_audio(const string &filename,vector<Base_audio_processor*> processors){
-
-	cerr<<"Rotor: starting audio analysis"<<endl;
+	Logger& logger = Logger::get("Rotor");
+	logger.information("Starting audio analysis");
 
 	libav::audioloader loader;
 	loader.setup(filename);
@@ -310,7 +340,7 @@ bool Render_context::load_audio(const string &filename,vector<Base_audio_process
 
 	for (auto p: processors) {
 		if(!p->init(channels,bits,samples,rate) ){
-			cerr<<"Plugin failed to initialse"<<endl;
+			logger.error("ERROR: Audio plugin failed to initialse");
 			return false;
 		}
 	}
@@ -339,7 +369,7 @@ bool Render_context::load_audio(const string &filename,vector<Base_audio_process
 		p->print_summary();
 	}
 
-	cerr<<"Rotor: finished audio analysis"<<endl;
+	logger.information("Finished audio analysis");
 	return true;
 }
 bool Render_context::load_video(const string &nodeID,const string &filename){
diff --git a/rotord/rotor.h b/rotord/rotor.h
index 1d0172f..136d812 100755
--- a/rotord/rotor.h
+++ b/rotord/rotor.h
@@ -17,6 +17,8 @@ http://stackoverflow.com/questions/5261658/how-to-seek-in-ffmpeg-c-c
 #include <math.h>
 #include <memory>
 #include <sys/time.h>
+#include <iostream>
+
 
 #include "Poco/Net/HTTPServer.h"
 #include "Poco/Net/HTTPResponse.h"
@@ -36,12 +38,13 @@ http://stackoverflow.com/questions/5261658/how-to-seek-in-ffmpeg-c-c
 #include "Poco/Base64Encoder.h"
 #include "Poco/Path.h"
 #include "Poco/StringTokenizer.h"
-#include <iostream>
+#include "Poco/Logger.h"
 
 
 using Poco::UUID;
 using Poco::UUIDGenerator;
 using Poco::Net::HTTPResponse;
+using Poco::Logger;
 
 /*
 extern "C" {
diff --git a/rotord/rotord.cpp b/rotord/rotord.cpp
index 77725ff..6f2d765 100755
--- a/rotord/rotord.cpp
+++ b/rotord/rotord.cpp
@@ -14,7 +14,7 @@ void RenderContextHandler::handleRequest(HTTPServerRequest& request,HTTPServerRe
 
     std::ostream& ostr = response.send();
 
-	ostr << "<?xml version='1.0' encoding='ISO-8859-1'?>\n";
+	ostr << "<?xml version='1.0' encoding='ISO-8859-1'?>\n"; //this is the mysterious extra header
 	ostr << content;
 
 }
@@ -22,12 +22,12 @@ void RenderContextHandler::handleRequest(HTTPServerRequest& request,HTTPServerRe
 
 HTTPRequestHandler* RotorRequestHandlerFactory::createRequestHandler(const HTTPServerRequest& request){
 	
-	Logger& logger = Logger::get("Rotor");
 
 	Poco::URI theuri=Poco::URI(request.getURI());
 	std::vector <std::string> command;
 	theuri.getPathSegments(command);
 
+	Logger& logger = Logger::get("Rotor");
 	logger.information(request.clientAddress().toString()+" "+request.getMethod());
 
 	HTTPResponse::HTTPStatus status=HTTPResponse::HTTP_BAD_REQUEST; //by default
@@ -52,7 +52,7 @@ HTTPRequestHandler* RotorRequestHandlerFactory::createRequestHandler(const HTTPS
 													//Throws a SystemException if no MAC address can be obtained.
 													//
 													//seems to hang, to me
-				logger.information("Rotor: starting thread "+sID);
+				logger.information("starting thread "+sID);
 				manager.start(new Rotor::Render_context(sID));
 				//XML.addTag("sID");
 				XML.addValue("sID",sID);
@@ -64,12 +64,13 @@ HTTPRequestHandler* RotorRequestHandlerFactory::createRequestHandler(const HTTPS
 					bool found=false;
 					for (auto& task: manager.taskList()) {
 						if(task->name()==sID) {
+							logger.error("ERROR: tried to create thread with existing name "+sID);
 							XML.addValue("error","Render context /"+sID+"/ exists already");
 							found=true;
 						}
 					}
 					if (!found){
-						cerr << "Rotor: starting thread "<< sID << endl;
+						logger.information("starting thread "+sID);
 						manager.start(new Rotor::Render_context(sID));
 						XML.addValue("sID",sID);
 						status=HTTPResponse::HTTP_OK;
@@ -80,6 +81,7 @@ HTTPRequestHandler* RotorRequestHandlerFactory::createRequestHandler(const HTTPS
 		else if (command[0]=="list") {
 			XML.pushTag("rotor");
 			if (request.getMethod()=="GET") {
+				logger.information("sending tasklist");
 												//std::list < Poco::AutoPtr < Poco::Task > >::iterator it;
 												//it=manager.taskList().begin();
 												//for (it=manager.taskList().begin();it !=manager.taskList().end();++it) {
@@ -97,6 +99,7 @@ HTTPRequestHandler* RotorRequestHandlerFactory::createRequestHandler(const HTTPS
 			}
 		}
 		else if (command[0]=="exit") {
+			logger.information("exiting");
 			exit(0);
 		}
 		else {
@@ -112,9 +115,11 @@ HTTPRequestHandler* RotorRequestHandlerFactory::createRequestHandler(const HTTPS
 						if (request.getMethod()=="DELETE") {
 							task->cancel();
 							status=HTTPResponse::HTTP_OK;
+							logger.information("deleted context "+command[0]);
 							XML.addValue("status","context deleted successfully");
 						}
 						else {
+							logger.error("ERROR: Render context invoked with no command: "+command[0]);
 							XML.addValue("error","Render context invoked with no command");
 					   	}
 				    }
@@ -138,13 +143,15 @@ HTTPRequestHandler* RotorRequestHandlerFactory::createRequestHandler(const HTTPS
 			}
 			if (!found) {
 				status=HTTPResponse::HTTP_NOT_FOUND;
+				logger.error("ERROR: context not found: "+command[0]);
 				XML.pushTag("rotor");
 				XML.addValue("error","Render context not found");
 			}
 		}
 	}
 	else {
-		XML.addValue("error","Emoty request");
+		logger.error("ERROR: Empty request");
+		XML.addValue("error","Empty request");
 	}
 	string content;
 	XML.copyXmlToString(content);
diff --git a/rotord/rotord.h b/rotord/rotord.h
index da987b0..7656c28 100755
--- a/rotord/rotord.h
+++ b/rotord/rotord.h
@@ -26,7 +26,6 @@
 #include <sstream>
 #include "Poco/URI.h"
 #include "Poco/Channel.h"
-#include "Poco/Logger.h"
 #include "Poco/SplitterChannel.h"
 #include "Poco/ConsoleChannel.h"
 #include "Poco/FormattingChannel.h"
@@ -107,6 +106,8 @@ class RotorServer: public Poco::Util::ServerApplication
 		bool _helpRequested;
 };
 
+RotorServer app; //needs to be global for logger
+
 int main(int argc, char** argv)
 {
 	AutoPtr<SplitterChannel> splitterChannel(new SplitterChannel());
@@ -130,6 +131,6 @@ int main(int argc, char** argv)
 	logger.information("starting rendering daemon");
 
 	HTTPStreamFactory::registerFactory();
-	RotorServer app;
+	
 	return app.run(argc, argv);
 }