Not executing commands until web browser refresh

[JHarding86]

I am seeing some strange behavior with the fauxapi. Since I haven’t received a response in the purging interface repo, I thought I would repost here.

Versions: I am using the latest from master: https://github.com/ndejong/pfsense_fauxapi_client_python I followed the installation procedure for pfSense fauxAPI: https://github.com/ndejong/pfsense_fauxapi

pfSense version is:

• 2.4.5-RELEASE (amd64)
• built on Tue Mar 24 15:25:50 EDT 2020
• FreeBSD 11.3-STABLE

My python client authenticates with pfSense and seems to be functional. I am setting the configuration with the function call:

result = self.FauxapiLib.config_set(self.system_config)

If I am not manually logged into my pfSense web portal via a web browser the fauxapi reports the following after making the call above:

PfsenseFauxapi.PfsenseFauxapi.PfsenseFauxapiException: (
  'Unable to complete config_set() request', {
    'callid': '5f51134ea4d8f', 
    'action': 'config_set', 
    'message': 'failed to set new config', 
    'logs': [
      {
        'INFO': '20200903Z100118 :: fauxapi\\v1\\fauxApi::__call', 
        'DATA': {'user_action': 'config_set', 'callid': '5f51134ea4d8f', 'client_ip': '192.168.1.77'}
      }, 
      {
        'ERROR': '20200903Z100222 :: unable confirm config reload before timeout', 
        'DATA': {'config_cache_filename': '/tmp/config.cache', 'timeout': 60}
      }, 
      {
        'WARN': '20200903Z100222 :: attempting to revert config to last known backup', 
        'DATA': {'last_backup_file': '/cf/conf/backup/config-1599148878.xml'}
      }, 
      {
        'INFO': '20200903Z100222 :: config file reverted to last known backup', 
        'DATA': {'config_file': '/cf/conf/backup/config-1599148878.xml'}
      }
    ]
  }
)

If I am logged into the pfSense web portal via my web browser and make the call to:

result = self.FauxapiLib.config_set(self.system_config)

and then click on any page, for example System->Advanced, then the call goes through perfectly:

{'callid': '5f5115d828cce', 'action': 'send_event', 'message': 'ok'}

It appears as though pfSense needs this 'trigger' to process the fauxapi commands. I thought this was super strange and figured I was missing something entirely that maybe you or someone else would know how to fix.

I have created a video of the issue as it happens, but it contains a lot of identifying information. I can PM you a link if necessary.

[ndejong]

Hi @JHarding86

I've reformatted your question a little to make it easier to follow.

Could you run the same command with --debug enabled to capture more logs and post them here?

The code location you are bumping into is here and it makes me think there is something not quite right about the configuration you are trying to set

Lets start with the --debug and diagnose from there .

[JHarding86]

I have enabled debug output. Here is the output a failed attempt

PfsenseFauxapi.PfsenseFauxapi.PfsenseFauxapiException: (
  'Unable to complete config_set() request', {
    'callid': '5f55ab931922f', 
    'action': 'config_set', 
    'message': 'failed to set new config', 
    'logs': [
      {
        'INFO': '20200906Z214003 :: fauxapi\\v1\\fauxApi::__call', 
        'DATA': {'user_action': 'config_set', 'callid': '5f55ab931922f', 'client_ip': '192.168.1.77'}
      }, 
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApi::__check_user_action_call'
      }, 
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApiAuth::is_authenticated'
      },
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApiAuth::load_credentials'
      },
      {
        'DEBUG': '20200906Z214003 :: valid auth for call', 
        'DATA': {'apikey': 'PFFAaddblockscript', 'callid': '5f55ab931922f', 'client_ip': '192.168.1.77'}
      }, 
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApiAuth::is_authorized'
      },
      {
        'DEBUG': '20200906Z214003 :: permit allows action', 
        'DATA': {'action': 'config_set', 'permit': 'config_*', 'permits': ['alias_*', 'config_*', 'gateway_*', 'rule_*', 'send_*', 'system_*', 'function_*']}
      }, 
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApi::__check_user_action_call() checks all passed'
      }, 
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApiActions::config_set'
      },
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApiPfsenseInterface::config_save', 
        'DATA': {'do_backup': True, 'do_reload': True}
      },
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApiPfsenseInterface::config_backup', 
        'DATA': '/cf/conf/config.xml'
      },
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApiPfsenseInterface::get_next_backup_config_filename', 
        'DATA': {'type': 'pfsense'}
      },
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApiPfsenseInterface::config_load', 
        'DATA': {'config_file': '/cf/conf/config.xml'}
      },
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApiPfsenseInterface::config_load',
        'DATA': {'config_file': '/cf/conf/backup/config-1599450003.xml'}
      },
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApiPfsenseInterface::config_load',
        'DATA': {'config_file': '/cf/conf/config.xml'}
      },
      {
        'DEBUG': '20200906Z214003 :: attempting to (re)load a temp copy of the config supplied',
        'DATA': {'config_temp_file': '/tmp/fauxApi_i0CxT0'}
      },
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApiPfsenseInterface::config_load',
        'DATA': {'config_file': '/tmp/fauxApi_i0CxT0'}
      }, 
      {
        'DEBUG': '20200906Z214003 :: confirmed the config supplied will reload into the same config supplied',
        'DATA': {'config_temp_file': '/tmp/fauxApi_i0CxT0'}
      }, 
      {
        'DEBUG': '20200906Z214003 :: fauxapi\\v1\\fauxApiPfsenseInterface::system_load_config',
        'DATA': '/cf/conf/config.xml'
      }, 
      {
        'DEBUG': '20200906Z214003 :: exec curl', 
        'DATA': {'exec_command': 'curl --silent --insecure "https://127.0.0.1:443/index.php?__fauxapi_callid=5f55ab931922f" > /dev/null'}
      }, 

      < REPEAT 60x >

      {
        'DEBUG': '20200906Z214105 :: exec curl', 
        'DATA': {'exec_command': 'curl --silent --insecure "https://127.0.0.1:443/index.php?__fauxapi_callid=5f55ab931922f" > /dev/null'}
      }, 
      {
        'ERROR': '20200906Z214106 :: unable confirm config reload before timeout', 
        'DATA': {'config_cache_filename': '/tmp/config.cache', 'timeout': 60}
      }, 
      {
        'WARN': '20200906Z214106 :: attempting to revert config to last known backup', 
        'DATA': {'last_backup_file': '/cf/conf/backup/config-1599450003.xml'}
      }, 
      {
        'INFO': '20200906Z214106 :: config file reverted to last known backup', 
        'DATA': {'config_file': '/cf/conf/backup/config-1599450003.xml'}
      }
    ]
  }
)

[JHarding86]

I just modified my code. Here is the function I created to prove to myself that I am not submitting a poorly structured configuration file:

def addToAlias(self):
    self.system_config = self.FauxapiLib.config_get()
    result = self.FauxapiLib.config_set(self.system_config)

This code still hangs until I hit a pfsense page with my browser

[JHarding86]

Any insights?

[ndejong]

I've formatted those logs for you and the issue becomes a lot easier to spot.

Notice all the repeated attempts to send a request to https://127.0.0.1:443/index.php - I'm guessing that you are running pfSense on a port other than 443 or you have rules to prevent connections from localhost?

Normally FauxAPI does a page request to the admin page itself to force pfSense to reload the config. This then explains the behavior you are describing where settings via FauxAPI were not being applied until you visit the web-interface. The fact that FauxAPI has to do this under the covers is frustrating, it generally has to do with the fact that the pfSense code often has controller calls and functions baked into view pages.

[JHarding86]

I did see that and kinda disregarded it because I am using port 443 and I have not setup any pfSense rules to explicitly block local host. Looking at my rules nothing that I have applies to local host that I can see. Although this is exactly what is happening because when I manually perform the curl command it fails. Hmmm, I don’t know what firewall rule would or even could block the localhost. Any recommendations for where or what to look for?

[JHarding86]

@ndejong Can you jump onto the net gate forums and chime in on the thread I started regarding this issue? It seems as though blocking the loopback is a strange/bewildering thing to do/have done.

Here is the thread: https://forum.netgate.com/topic/156783/loopback-address-being-blocked

[JHarding86]

It turns out, my pfSense had somehow messed up the interface that the loopback address was associated with. A simple restart of the pfSense virtual machine and the loopback was reassigned to the proper interface (lo0). Thanks for the help. Sorry for being a bother with something that was not an issue with the faux api.