def log_message(self, format, *args):
     #args: ('POST /weblab/xmlrpc/ HTTP/1.1', '200', '-')
     log.log(
         XmlRpcRequestHandler,
         log.level.Info,
         "Request from %s: %s" % (get_context().get_ip_address(), format % args)
     )

 def log_message(self, format, *args):
     #args: ('POST /foo/bar/ HTTP/1.1', '200', '-')
     log.log(
         WebHttpHandler,
         log.level.Info,
         "Request from %s: %s" % (get_context().get_ip_address(), format % args)
     )

    def do_send_command_to_device(self, command):
        
        if command == "POLL":
            if self._gpib_launcher.poll():
                log.log(
                    UdGpibExperiment,
                    log.level.Info,
                    "Executed, saving results"
                )
                self._remove_file()
                return "OK"
            else:
                return "WAIT"
        
        elif command == "RESULT code":
            return self._gpib_launcher.get_result_code()

        elif command == "RESULT stdout":
            return self._remove_non_ascii_characters(self._gpib_launcher.get_result_stdout())

        elif command == "RESULT stderr":
            return self._remove_non_ascii_characters(self._gpib_launcher.get_result_stderr())
        
        elif command == "RESULT file":
            try:
                return "OK%s" % self._remove_non_ascii_characters(self._read_output_file())
            except Exception:
                return "ERFile <%s> not found"  % self._cfg_manager.get_value('gpib_public_output_file_filename')
                
        else:
            raise GpibErrors.UnknownUdGpibCommandError("Unknown received command: %s" % command)

    def _iterate(self, element):
        elements = [element]
        while True:
            try:
                new_element = self.queue.get_nowait()
                elements.append(new_element)
            except Queue.Empty:
                break

        if not self.stopped:
            execute = True
            with self.period_lock:
                if time.time() - self._latest_update <= self.next_period_between_updates:
                    execute = False
                else:
                    self._latest_update = time.time()
                    self._update_period_between_updates()

            if execute:
                try:
                    self.scheduler.update()
                except:
                    log.log(SchedulerTransactionsSynchronizer, log.level.Critical, "Exception updating scheduler")
                    log.log_exc(SchedulerTransactionsSynchronizer, log.level.Critical)


        self._notify_elements(elements)

    def _program_file(self, file_content):
        try:
            fd, file_name = tempfile.mkstemp(
                prefix="ud_xilinx_experiment_program", suffix="." + self._xilinx_impact.get_suffix()
            )
            try:
                try:
                    # TODO: encode? utf8?
                    if isinstance(file_content, unicode):
                        file_content_encoded = file_content.encode("utf8")
                    else:
                        file_content_encoded = file_content
                    file_content_recovered = ExperimentUtil.deserialize(file_content_encoded)
                    os.write(fd, file_content_recovered)
                finally:
                    os.close(fd)
                self._programmer.program(file_name)
            finally:
                os.remove(file_name)
                # print file_name
                # import sys
                # sys.stdout.flush()
        except Exception as e:

            # TODO: test me
            log.log(UdXilinxExperiment, log.level.Info, "Exception joining sending program to device: %s" % e.args[0])
            log.log_exc(UdXilinxExperiment, log.level.Debug)
            raise ExperimentErrors.SendingFileFailureError("Error sending file to device: %s" % e)
        self._clear()

    def _send_async_command_t(self, session, command):
        """
        This method is used for asynchronously calling the experiment server's
        send_command_to_device, and for that purpose runs on its own thread.
        This implies that its response will arrive asynchronously to the client.
        """
        
        lab_session_id = session['session_id']
        experiment_instance_id = session['experiment_instance_id']
        api = self._assigned_experiments.get_api(experiment_instance_id)
        
        experiment_coord_address = session['experiment_coord_address']
        experiment_server = self._locator[experiment_coord_address]

        try:
            if api.endswith("concurrent"):
                response = experiment_server.send_command_to_device(lab_session_id, command.get_command_string())
            else:
                response = experiment_server.send_command_to_device(command.get_command_string())
        except Exception as e:
            log.log( LaboratoryServer, log.level.Warning, "Exception sending async command to experiment: %s" % e )
            log.log_exc(LaboratoryServer, log.level.Info)
            raise LaboratoryErrors.FailedToSendCommandError("Couldn't send async command: %s" % str(e))

        return Command.Command(str(response))

    def _retrieve_all_servers_from_coordinator(self,original_server_address,server_type,restrictions):
        try:
            return self._coordinator.get_all_servers(original_server_address,server_type,restrictions)
        except ProtocolErrors.ProtocolError as pe:
            # TODO: not unittested
            log.log(
                    ServerLocator,
                    log.level.Error,
                    "Problem while asking for all servers to the coordinator server. %s" % pe
                )
            log.log_exc(
                    ServerLocator,
                    log.level.Warning
                )

            raise LocatorErrors.ProblemCommunicatingWithCoordinatorError(
                    "Couldn't retrieve all servers from coordinator server: " + str(pe),
                    pe
                )
        except Exception as e:
            # TODO: not unittested
            log.log(
                    ServerLocator,
                    log.level.Error,
                    "Unexpected exception while asking for all servers to the coordinator server. %s" % e
                )
            log.log_exc(
                    ServerLocator,
                    log.level.Warning
                )

            raise LocatorErrors.ProblemCommunicatingWithCoordinatorError(
                    "Unexpected exception while asking all servers from coordinator server: " + str(e),
                    e
                )

 def _skeleton(self,*parameters,**kparameters):
     """ Dynamically generated method. Protocol: SOAP.
          Method name: METHOD_NAME. Documentation: DOCUMENTATION """
     try:
         if SERIALIZE:
             parameters_instance = pickle.loads(parameters[0])
             if SERIALIZE_MAPPING:
                 parameters_instance = mapper.load_from_dto(parameters_instance)
             params, kparams = parameters_instance
             result = getattr(self._parent,'do_'+METHOD_NAME)(
                         *params,
                         **kparams
                     )
             if SERIALIZE_MAPPING:
                 result = mapper.dto_generator(result)
             dumped_result = pickle.dumps(result)
             return dumped_result
         else:
             return getattr(self._parent,'do_'+METHOD_NAME)(*parameters,**kparameters)
     except Exception as e:
         # TODO: watch out, if server gets a Control + C, the exception is going to propagate
         tb = traceback.format_exc()
         if type(e) == types.InstanceType:
             class_name = str(e.__class__)
         else:
             class_name = type(e).__module__ + '.' + type(e).__name__
         log.log(self,log.level.Info,"Exception : " + class_name + "; " + e.args[0] + "; " + tb)
         raise SOAPpy.faultType(
                 faultcode=class_name,
                 faultstring=e.args[0],
                 detail=tb
             )

    def _execute(self, cmd_params, digilent_adept):
        # Kludge!
        full_cmd_line = digilent_adept + cmd_params.split(" ")

        log.log(DigilentAdept,log.level.Warning,"Executing %s" % full_cmd_line)

        try:
            popen = subprocess.Popen(
                full_cmd_line,
                stdin  = subprocess.PIPE,
                stdout = subprocess.PIPE,
                stderr = subprocess.PIPE
            )
        except Exception as e:
            raise ErrorProgrammingDeviceError(
                "There was an error while executing Digilent Adept: %s" % e
            )
        # TODO: make use of popen.poll to make this asynchronous
        try:
            result = popen.wait()
        except Exception as e:
            raise ErrorWaitingForProgrammingFinishedError(
                "There was an error while waiting for Digilent Adept to finish: %s" % e
            )

        try:
            stdout_result = popen.stdout.read()
            stderr_result = popen.stderr.read()
        except Exception as e:
            raise ErrorRetrievingOutputFromProgrammingProgramError(
                "There was an error while retrieving the output of Digilent Adept: %s" % e
            )
        return result, stdout_result, stderr_result

 def wrapped(self, *args, **kargs):
     if not SERIAL_AVAILABLE:
         msg = "The optional library 'pyserial' is not available. The experiments trying to use the serial port will fail."
         print(msg, file=sys.stderr)
         log.log(self, log.level.Error, msg)
         return
     return func(self, *args, **kargs)

        def _register_soap_server(self,who,port):
            if SOAPPY_AVAILABLE:
                _soap_server_lock.acquire()
                try:
                    global _soap_server
                    if _soap_server == None:
                        _soap_server = {}
                    if not _soap_server.has_key(port):
                        _soap_server[port] = _AvoidTimeoutSOAPServer((who,port))
                        _soap_server[port].config.dumpFaultInfo = 0
                        _soap_server[port].socket.settimeout(MAX_TIMEOUT)
                    self.server = _soap_server[port]

                    if port not in _soap_server_functions:
                        _soap_server_functions[port] = []

                    for method_name in all_methods:
                        if method_name in _soap_server_functions[port]:
                            log.log(ServerSOAP,log.level.Warning,'Method "%s" already served by server "%s" on port %s' % (method_name,self, port))
                        #Register every function from "all_methods"
                        self.server.registerFunction(new.instancemethod(getattr(self.__class__, method_name),self,self.__class__))
                        _soap_server_functions[port].append(method_name)
        
                finally:
                    _soap_server_lock.release()
            else:
                msg = "The optional library 'SOAPpy' is not available. The communications between different servers will not work through SOAP."
                print >> sys.stderr, msg
                log.log(self, log.level.Error, msg)
                class FakeServer(object):
                    def handle_request(self):
                        time.sleep(MAX_TIMEOUT)
                self.server = FakeServer()

    def create_external_user(self, external_user, external_id, system, group_names):
        session = self.Session()
        try:
            try:
                auth_type = session.query(model.DbAuthType).filter_by(name=system).one()
                auth = auth_type.auths[0]
            except (NoResultFound, KeyError):
                raise DbErrors.DbUserNotFoundError("System '%s' not found in database" % system)

            groups = []
            for group_name in group_names:
                try:
                    group = session.query(model.DbGroup).filter_by(name=group_name).one()
                except NoResultFound:
                    raise DbErrors.DbUserNotFoundError("Group '%s' not found in database" % group_name)
                groups.append(group)

            try:
                role = session.query(model.DbRole).filter_by(name=external_user.role.name).one()
                user = model.DbUser(external_user.login, external_user.full_name, external_user.email, role = role)
                user_auth = model.DbUserAuth(user, auth, configuration = external_id)
                for group in groups:
                    group.users.append(user)
                session.add(user)
                session.add(user_auth)
                session.commit()
            except Exception as e:
                log.log( DatabaseGateway, log.level.Warning, "Couldn't create user: %s" % e)
                log.log_exc(DatabaseGateway, log.level.Info)
                raise DbErrors.DatabaseError("Couldn't create user! Contact administrator")
        finally:
            session.close()

    def get_data_type(self):
        def is_builtin():
            if not hasattr(self.element, "__class__"):
                return False
            return self.element.__class__ == __builtin__.__dict__.get(self.element.__class__.__name__)

        if type(self.element) in _basic_normal_types:
            return _Node.BASIC
        elif type(self.element) == tuple:
            return _Node.TUPLE
        elif type(self.element) == list:
            return _Node.LIST
        elif type(self.element) == dict:
            return _Node.DICT
        elif is_builtin() or isinstance(self.element, _DtoBuiltin):
            return _Node.BUILTIN_E
        elif isinstance(self.element, Exception):
            return _Node.EXCEPTION
        elif type(self.element) == _new.instance:
            return _Node.INSTANCE
        elif hasattr(self.element, "__reduce__") or hasattr(self.element, "__reduce_ex__"):
            return _Node.OBJECT
        else:
            _log.log(
                _Node,
                _log.level.Warning,
                "Unrecognized type: %s, %r, %r. Configure it at voodoo.mapper.py"
                % (type(self.element), self.name, self.parent),
            )
            return _Node.IGNORABLE

    def _find_api(self, experiment_instance_id, experiment_coord_address = None):
        """
        _find_api(experiment_instance_id)
        
        Tries to retrieve the API version of the specified experiment.
        
        @param experiment_instance_id Experiment instance identifier for the experiment whose API 
        we want.
        @param experiment_coord_address Experiment coord address. May be None.
        @return API version, as a string. Will return the current API if for any reason
        it is unable to obtain the version.
        """
        
        # Check whether we know the API version already.
        api = self._assigned_experiments.get_api(experiment_instance_id)

        # If we don't know the API version yet, we will have to ask the experiment server itself
        if api is None:
            reported_api = self._get_experiment_api(experiment_instance_id)
            if reported_api is None:
                log.log( LaboratoryServer, log.level.Warning, "It was not possible to find out the api version of %r. Using current version as default."
                         % experiment_coord_address)
                if DEBUG:
                    print "[DBG] Was not possible to find out the api version of %r" % experiment_coord_address
            else:
                # Remember the api version that we retrieved
                self._assigned_experiments.set_api(experiment_instance_id, reported_api)
                api = reported_api

        # If we don't know the api, we will use the current version as default.
        if api is None:
            api = ExperimentApiLevel.current
            self._assigned_experiments.set_api(experiment_instance_id, api)
            
        return api

    def run(self):
        while not self.stopping:
            try:
                sleep(1)
                if self.frequency is None:
                    continue
                # Here self.frequency is configured, so wait the rest of the required time
                if self.frequency > 1:
                    sleep(self.frequency - 1)

                if self.stopping:
                    break

                if self.coordinator is None:
                    continue

                coordinator = self.coordinator()
                if coordinator is None or coordinator.locator is None:
                    continue # coordinator not configured yet
                checker = self.Checker(coordinator)
                checker.check()
            except Exception as e:
                log.log(ResourcesCheckerThread, log.level.Critical,
                    "Exception checking resources: %s" % e )
                log.log_exc(ResourcesCheckerThread, log.level.Error)

    def _free_experiment(self, lab_session_id):
        if not self._session_manager.has_session(lab_session_id):
            return

        session = self._session_manager.get_session_locking(lab_session_id)
        finished = True
        experiment_response = None
        try:
            # Remove the async requests whose results we have not retrieved.
            # It seems that they might still be running when free gets called.
            # TODO: Consider possible issues.
            session_id = session['session_id']
            if session_id in self._async_requests:
                del self._async_requests[session_id]

            experiment_instance_id = session['experiment_instance_id']
            try:
                experiment_response = self._free_experiment_from_assigned_experiments(experiment_instance_id, lab_session_id)
            except Exception as e:
                log.log( LaboratoryServer, log.level.Error, "Exception freeing experiment" % e )
                log.log_exc(LaboratoryServer, log.level.Error)
                experiment_response = ''

            if experiment_response is not None and experiment_response.lower() != 'ok' and experiment_response != '':
                try:
                    response = json.loads(experiment_response)
                    finished = response.get(Coordinator.FINISH_FINISHED_MESSAGE)
                except:
                    traceback.print_exc()
        finally:
            if finished:
                self._session_manager.delete_session_unlocking(lab_session_id)
            else:
                self._session_manager.modify_session_unlocking(lab_session_id, session)
            return experiment_response

    def _execute(self, cmd_params, xcs3prog_full_path):
        """
        Runs the actual process with the given command line arguments and full path.
        :param cmd_params:
        :param xcs3prog_full_path:
        :return:
        """

        full_cmd_line = xcs3prog_full_path + cmd_params.split(" ")

        log.log(Xcs3prog, log.level.Warning, "Executing %s" % full_cmd_line)

        try:
            popen = subprocess.Popen(
                full_cmd_line, stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=subprocess.PIPE
            )
        except Exception as e:
            raise ErrorProgrammingDeviceError(
                "There was an error while executing xcs3prog FPGA programming tool: %s" % e
            )

        try:
            stdout, stderr = popen.communicate("N\n")
            result = popen.wait()
        except Exception as e:
            raise ErrorWaitingForProgrammingFinishedError(
                "There was an error while waiting for xcs3prog FPGA programming tool to finish: %s" % e
            )

        return result, stdout, stderr

    def _test_server(self,server,address):
        """ _test_server(self,server,address) -> bool

        It returns True (if we could perform a call to "test_me"), or False (if we couldn't)
        """
        # Check if the server is up and running
        try:
            random_msg = str(random.random())
            result_msg = server.test_me(random_msg)
            if random_msg != result_msg:
                # This was not a valid server, try another
                log.log(
                    ServerLocator,
                    log.level.Warning,
                    "Test message received from server %s different from the message sent (%s vs %s). Trying another server" %(
                        address.address,
                        random_msg,
                        result_msg
                    )
                )
                return False
        except Exception as e:
            #There was a exception: this is not a valid server, try another
            log.log(
                ServerLocator,
                log.level.Warning,
                "Testing server %s raised exception %s. Trying another server" % (
                    address.address,
                    e
                )
            )
            log.log_exc(ServerLocator, log.level.Info)
            return False
        else:
            return True

    def run(self):
        try:
            try:
                self.result = self._func(
                    self._self,
                    *self._args,
                    **self._kargs
                )
                self.finished_ok = True
            finally:
                if self._resource_manager != None:
                    self._resource_manager.remove_resource(self)
        except Exception as e:
            self.raised_exc = e
            if self.logging:
                log.log(
                    _ThreadedFunc,
                    log.level.Warning,
                    "threaded: exception caught while running %s: %s" % (
                            self._func.__name__,
                            e
                        )
                )
                log.log_exc( _ThreadedFunc, log.level.Warning)

            sio = StringIO.StringIO()
            traceback.print_exc(file=sio)
            self.raised_exc_traceback = sio.getvalue()

 def _get_server_from_coordinator(self, session_id):
     try:
         return self._coordinator.get_server(session_id)
     except CoordinatorServerErrors.NoServerFoundError as nsfe:
         raise nsfe
     except ProtocolErrors.ProtocolError as pe:
         log.log(
                 ServerLocator,
                 log.level.Error,
                 "Problem while asking for other server to the coordinator server. %s" % pe
             )
         log.log_exc(
                 ServerLocator,
                 log.level.Warning
             )
         raise LocatorErrors.ProblemCommunicatingWithCoordinatorError(
                 "Couldn't ask for other server to coordinator server: " + str(pe),
                 pe
             )
     except Exception as e:
         log.log(
                 ServerLocator,
                 log.level.Error,
                 "Unexpected exception while asking for other server to the coordinator server. %s" % e
             )
         log.log_exc(
                 ServerLocator,
                 log.level.Warning
             )
         raise LocatorErrors.ProblemCommunicatingWithCoordinatorError(
                 "Unexpected exception while asking for other server to the coordinator server: " + str(e),
                 e
             )