Packetfence 9.3.0 fingerbank error malformed json string error

[rokkhan]

Hi, I have just deployed a new server with latest packetfence versión available 9.3.0 and it looks that fingerbank can not identify device type.

The logs show this error:

Feb 7 20:21:53 SLX00010808 packetfence: ERROR pfperl-api(2593): malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "(end of string)") at /usr/local/pf/lib/fingerbank/Model/Device.pm line 122. (Mojolicious::Plugin::DefaultHelpers::_development)

It happens with every device I try and all nodes fingerbank info looks like this.

If I click on Refresh Fingerbank i also get same log error.

Fingerbank databases updates without any issue.

Any clue?

Greetings.

[rokkhan]

Devices is recognized as it says that got device: 3809

Feb 7 20:31:49 SLX00010808 packetfence: INFO pfperl-api(2593): Successfully interrogate upstream Fingerbank project for matching. Got device : 3809 (fingerbank::Source::Collector::match) Feb 7 20:31:50 SLX00010808 packetfence: ERROR pfperl-api(2593): malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "(end of string)") at /usr/local/pf/lib/fingerbank/Model/Device.pm line 122. (Mojolicious::Plugin::DefaultHelpers::_development)

And it is an Samsung Device as it shows in the devices database:

But this infor is not stored in nodes information database.

[julsemaan]

Please provide the following files via direct email to support@inverse.ca:

• /usr/local/fingerbank/conf/fingerbank.conf
• /usr/local/fingerbank/db/fingerbank_Local.db

Also, in this issue, post the content of fingerbank.log while you're trying the profiling.

Thanks,

[rokkhan]

Hi, here you got the fingerbank.log and i will send you by email the .conf and local.db by email. fingerbank.log Thanks a lot!

[julsemaan]

I can't seem to find or replicate the issue with what you provided.

Could you do the following on your server:

cd /usr/local/fingerbank
curl https://gist.githubusercontent.com/julsemaan/e1905d390c179223e507cc2c97e58209/raw/22b33b105e2d5704b103281129786889249c6f14/5129-add-logging.patch
/usr/local/pf/bin/pfcmd service pf restart

Then try again in the admin and gather the logs in packetfence.log, it should contain an additional piece of info I'll be able to use to pinpoint the issue

[rokkhan]

Done: curl https://gist.githubusercontent.com/julsemaan/e1905d390c179223e507cc2c97e58209/raw/22b33b105e2d5704b103281129786889249c6f14/5129-add-logging.patch

diff --git a/lib/fingerbank/Model/Device.pm b/lib/fingerbank/Model/Device.pm index 9115823..1e65aae 100644 --- a/lib/fingerbank/Model/Device.pm +++ b/lib/fingerbank/Model/Device.pm @@ -118,6 +118,7 @@ sub is_a { my $req = $api->build_request("GET", "/api/v2/devices/$arg/is_a/$condition");

     my $res = $api->get_lwp_client->request($req);

• $logger->info("DECODED CONTENT: ".$res->decoded_content); if ($res->is_success) { my $result = decode_json($res->decoded_content); $logger->debug("Device $arg is a $condition. ".$result->{message});

Packetfence.log:

Feb 14 15:19:03 SLX00010808 packetfence: INFO pfcmd.pl(6123): Daemon pf took 43.250 seconds to start. (pf::services::manager::launchService) Feb 14 15:20:37 SLX00010808 packetfence_httpd.aaa: httpd.aaa(7337) INFO: [mac:40:a1:08:f5:c2:ac] handling radius autz request: from switch_ip => (172.22.15.144), connection_type => Wireless-802.11-NoEAP,switch_mac => (b8:50:01:c0:90:14), mac => [40:a1:08:f5:c2:ac], port => 1, username => "40-A1-08-F5-C2-AC", ssid => ATARI (pf::radius::authorize) Feb 14 15:20:37 SLX00010808 packetfence_httpd.aaa: httpd.aaa(7337) INFO: [mac:40:a1:08:f5:c2:ac] Instantiate profile BYOD-CONN (pf::Connection::ProfileFactory::_from_profile) Feb 14 15:20:37 SLX00010808 packetfence_httpd.aaa: httpd.aaa(7337) WARN: [mac:40:a1:08:f5:c2:ac] Switch type 'pf::Switch::Motorola::RFS' does not support MABFloatingDevices (pf::SwitchSupports::ANON) Feb 14 15:20:37 SLX00010808 packetfence_httpd.aaa: httpd.aaa(7337) WARN: [mac:40:a1:08:f5:c2:ac] Can't find provisioner for 40:a1:08:f5:c2:ac since we don't have it's OS (pf::Connection::Profile::findProvisioner) Feb 14 15:20:37 SLX00010808 packetfence_httpd.aaa: httpd.aaa(7337) INFO: [mac:40:a1:08:f5:c2:ac] Found authentication source(s) : 'metaldap' for realm 'null' (pf::config::util::filter_authentication_sources) Feb 14 15:20:37 SLX00010808 packetfence_httpd.aaa: httpd.aaa(7337) INFO: [mac:40:a1:08:f5:c2:ac] Connection type is MAC-AUTH. Getting role from node_info (pf::role::getRegisteredRole) Feb 14 15:20:37 SLX00010808 packetfence_httpd.aaa: httpd.aaa(7337) INFO: [mac:40:a1:08:f5:c2:ac] Username was defined "40-A1-08-F5-C2-AC" - returning role 'BYOD' (pf::role::getRegisteredRole) Feb 14 15:20:37 SLX00010808 packetfence_httpd.aaa: httpd.aaa(7337) INFO: [mac:40:a1:08:f5:c2:ac] PID: "i0874", Status: reg Returned VLAN: (undefined), Role: BYOD (pf::role::fetchRoleForNode) Feb 14 15:20:37 SLX00010808 packetfence_httpd.aaa: httpd.aaa(7337) WARN: [mac:40:a1:08:f5:c2:ac] No parameter BYOD Vlan found in conf/switches.conf for the switch 172.22.15.144 (pf::Switch::getVlanByName) Feb 14 15:20:37 SLX00010808 packetfence_httpd.aaa: httpd.aaa(7337) INFO: [mac:[undef]] Updating locationlog from accounting request (pf::api::handle_accounting_metadata) Feb 14 15:20:37 SLX00010808 packetfence_httpd.aaa: httpd.aaa(7337) WARN: [mac:[undef]] Switch type 'pf::Switch::Motorola::RFS' does not support RoamingAccounting (pf::SwitchSupports::ANON) Feb 14 15:20:40 SLX00010808 pfqueue: pfqueue(7462) WARN: [mac:40:a1:08:f5:c2:ac] Unable to match MAC address to IP '172.22.172.19' (pf::ip4log::ip2mac) Feb 14 15:20:40 SLX00010808 pfipset[7197]: t=2020-02-14T15:20:40+0000 lvl=info msg="Syncing to peers" pid=7197 request-uuid=8f77239b-4f3d-11ea-8824-005056b776be Feb 14 15:20:40 SLX00010808 pfipset[7197]: t=2020-02-14T15:20:40+0000 lvl=info msg="Syncing to peers" pid=7197 request-uuid=8f7875ae-4f3d-11ea-8824-005056b776be Feb 14 15:20:40 SLX00010808 pfqueue: pfqueue(7458) WARN: [mac:40:a1:08:f5:c2:ac] Unable to pull accounting history for device 40:a1:08:f5:c2:ac. The history set doesn't exist yet. (pf::accounting_events_history::latest_mac_history) Feb 14 15:20:41 SLX00010808 pfqueue: pfqueue(7458) ERROR: [mac:unknown] Error handling fingerbank_process : malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "(end of string)") at /usr/local/pf/lib/fingerbank/Model/Device.pm line 122. (pf::api::can_fork::notify)

Hope this will help!

Thanks.

[rokkhan]

Pecketfence.log when I click "Refresh Fingerbank" in Nodes.

Feb 14 15:25:18 SLX00010808 packetfence: INFO pfperl-api(7345): Database /usr/local/fingerbank/db/fingerbank_Local.db was changed or handles weren't initialized. Creating handle. (fingerbank::DB::SQLite::build_handle) Feb 14 15:25:18 SLX00010808 packetfence: WARN pfperl-api(7345): Cannot find any combination ID in any schemas (fingerbank::Source::LocalDB::_getCombinationID) Feb 14 15:25:18 SLX00010808 packetfence: INFO pfperl-api(7345): Upstream is configured and unable to fullfil an exact match locally. Will ignore result from local database (fingerbank::Source::LocalDB::match) Feb 14 15:25:18 SLX00010808 packetfence: INFO pfperl-api(7345): Successfully interrogate upstream Fingerbank project for matching. Got device : 60147 (fingerbank::Source::Collector::match) Feb 14 15:25:18 SLX00010808 packetfence: INFO pfperl-api(7345): Database /usr/local/fingerbank/db/fingerbank_Upstream.db was changed or handles weren't initialized. Creating handle. (fingerbank::DB::SQLite::build_handle) Feb 14 15:25:19 SLX00010808 packetfence: ERROR pfperl-api(7345): malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "(end of string)") at /usr/local/pf/lib/fingerbank/Model/Device.pm line 122. (Mojolicious::Plugin::DefaultHelpers::_development)

[julsemaan]

Sorry, the commands I gave were missing a pretty critical part which is to apply the patch :)

Retry with:

cd /usr/local/fingerbank
curl https://gist.githubusercontent.com/julsemaan/e1905d390c179223e507cc2c97e58209/raw/22b33b105e2d5704b103281129786889249c6f14/5129-add-logging.patch | patch -p1
/usr/local/pf/bin/pfcmd service pf restart

[rokkhan]

Hi, I am out of the office. I can patch and run refresh fingerbank in a node, but I can not reproduce the entire process. Do you think this test is relevant or is it better to wait to reproduce full scenario? Thanks in advance!

[rokkhan]

Thanks a lot!! After patching looks that now is working. Do I have to do anything else?

curl https://gist.githubusercontent.com/julsemaan/e1905d390c179223e507cc2c97e58209/raw/22b33b105e2d5704b103281129786889249c6f14/5129-add-logging.patch | patch -p1 % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 100 600 100 600 0 0 1116 0 --:--:-- --:--:-- --:--:-- 1115 patching file lib/fingerbank/Model/Device.pm

Fingerbank.log Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:40:a1:08:f5:c2:ac] Database /usr/local/fingerbank/db/fingerbank_Local.db was changed or handles weren't initialized. Creating handle. (fingerbank::DB::SQLite::build_handle) Feb 17 16:21:16 SLX00010808 /usr/local/fingerbank/collector/fingerbank-collector[15000]: t=2020-02-17T16:21:16+0000 lvl=info msg="Found IP/MAC (ip:192.168.176.103|mac:005056b7206e) on the local interface" pid=15000 Feb 17 16:21:16 SLX00010808 /usr/local/fingerbank/collector/fingerbank-collector[15000]: t=2020-02-17T16:21:16+0000 lvl=info msg="Discovered new endpoint: 005056b7206e - 192.168.176.103" pid=15000 Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:40:a1:08:f5:c2:ac] Database /usr/local/fingerbank/db/fingerbank_Upstream.db was changed or handles weren't initialized. Creating handle. (fingerbank::DB::SQLite::build_handle) Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:40:a1:08:f5:c2:ac] Searching for 'Device' entries in schema(s) returned an empty set (fingerbank::Base::CRUD::search) Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:40:a1:08:f5:c2:ac] Searching for 'DHCP6_Enterprise' entries in schema(s) returned an empty set (fingerbank::Base::CRUD::search) Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:40:a1:08:f5:c2:ac] Searching for 'DHCP6_Fingerprint' entries in schema(s) returned an empty set (fingerbank::Base::CRUD::search) Feb 17 16:21:16 SLX00010808 fingerbank-collector: [GIN] 2020/02/17 - 16:21:16 | 200 | 387.44µs | 127.0.0.1 | GET /endpoint_data/40:a1:08:f5:c2:ac Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:unknown] Searching for 'User_Agent' entries in schema(s) returned an empty set (fingerbank::Base::CRUD::search) Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) WARN: [mac:unknown] Cannot find any ID for 'User_Agent' with value '' (fingerbank::Source::LocalDB::ANON) Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:unknown] Searching for 'DHCP6_Fingerprint' entries in schema(s) returned an empty set (fingerbank::Base::CRUD::search) Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) WARN: [mac:unknown] Cannot find any ID for 'DHCP6_Fingerprint' with value '' (fingerbank::Source::LocalDB::ANON) Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:unknown] Searching for 'DHCP6_Enterprise' entries in schema(s) returned an empty set (fingerbank::Base::CRUD::search) Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) WARN: [mac:unknown] Cannot find any ID for 'DHCP6_Enterprise' with value '' (fingerbank::Source::LocalDB::ANON) Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) WARN: [mac:unknown] Cannot find any combination ID in any schemas (fingerbank::Source::LocalDB::_getCombinationID) Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:unknown] Upstream is configured and unable to fullfil an exact match locally. Will ignore result from local database (fingerbank::Source::LocalDB::match) Feb 17 16:21:16 SLX00010808 fingerbank-collector: [GIN] 2020/02/17 - 16:21:16 | 200 | 167.786797ms | 127.0.0.1 | GET /endpoint_data/40:a1:08:f5:c2:ac/details Feb 17 16:21:16 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:unknown] Successfully interrogate upstream Fingerbank project for matching. Got device : 60147 (fingerbank::Source::Collector::match) Feb 17 16:21:17 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:unknown] DECODED CONTENT: {"message":"Phone, Tablet or Wearable/Generic Android/Lenovo Android/Lenovo TBD is neither a child or a derivation of Operating System/Apple OS/Mac OS X or macOS","result":false} (fingerbank::Model::Device::ANON) Feb 17 16:21:18 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:unknown] DECODED CONTENT: {"message":"Phone, Tablet or Wearable/Generic Android/Lenovo Android/Lenovo TBD is neither a child or a derivation of Operating System/Windows OS/Windows Phone OS","result":false} (fingerbank::Model::Device::ANON) Feb 17 16:21:19 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:unknown] DECODED CONTENT: {"message":"Phone, Tablet or Wearable/Generic Android/Lenovo Android/Lenovo TBD is a virtual child of Operating System/Google OS/Android OS","result":true} (fingerbank::Model::Device::ANON) Feb 17 16:21:19 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:40:a1:08:f5:c2:ac] Searching for 'DHCP6_Enterprise' entries in schema(s) returned an empty set (fingerbank::Base::CRUD::search) Feb 17 16:21:19 SLX00010808 fingerbank: pfqueue(14913) INFO: [mac:40:a1:08:f5:c2:ac] Searching for 'DHCP6_Fingerprint' entries in schema(s) returned an empty set (fingerbank::Base::CRUD::search) Feb 17 16:21:32 SLX00010808 /usr/local/fingerbank/collector/fingerbank-collector[15000]: t=2020-02-17T16:21:32+0000 lvl=warn msg="Couldn't find a peer that has more uptime than this collector. Will not sync from anybody." pid=15000 Feb 17 16:21:32 SLX00010808 /usr/local/fingerbank/collector/fingerbank-collector[15000]: t=2020-02-17T16:21:32+0000 lvl=info msg="Unable to find a peer to sync from" pid=15000 Feb 17 16:21:47 SLX00010808 fingerbank_httpd.aaa: httpd.aaa(14814) INFO: [mac:40:a1:08:f5:c2:ac] Database /usr/local/fingerbank/db/fingerbank_Local.db was changed or handles weren't initialized. Creating handle. (fingerbank::DB::SQLite::build_handle) Feb 17 16:21:48 SLX00010808 fingerbank_httpd.aaa: httpd.aaa(14814) INFO: [mac:40:a1:08:f5:c2:ac] Database /usr/local/fingerbank/db/fingerbank_Upstream.db was changed or handles weren't initialized. Creating handle. (fingerbank::DB::SQLite::build_handle)

Packetfence.log

Feb 17 16:21:16 SLX00010808 pfqueue: pfqueue(14910) WARN: [mac:40:a1:08:f5:c2:ac] Unable to match MAC address to IP '172.22.172.19' (pf::ip4log::ip2mac) Feb 17 16:21:16 SLX00010808 packetfence_httpd.aaa: httpd.aaa(14814) INFO: [mac:[undef]] Instantiate profile BYOD-CONN (pf::Connection::ProfileFactory::_from_profile) Feb 17 16:21:16 SLX00010808 pfqueue: pfqueue(14913) WARN: [mac:40:a1:08:f5:c2:ac] Unable to pull accounting history for device 40:a1:08:f5:c2:ac. The history set doesn't exist yet. (pf::accounting_events_history::latest_mac_history) Feb 17 16:21:19 SLX00010808 pfqueue: pfqueue(14913) INFO: [mac:unknown] Device Lenovo TBD is a Android OS (pf::fingerbank::ANON) Feb 17 16:21:19 SLX00010808 pfqueue: pfqueue(14913) WARN: [mac:40:a1:08:f5:c2:ac] Unable to pull accounting history for device 40:a1:08:f5:c2:ac. The history set doesn't exist yet. (pf::accounting_events_history::latest_mac_history)

[julsemaan]

The patching only added more debug and didn't fix anything.

You'll have to check if it happens again and provide the updated logs.

[julsemaan]

Are you able to provide the new logs of that failure? Otherwise we'll close this