Persistent store error

[rssluca]

Hello,

I am getting this error when I try to show provisioning

2018-05-02 10:30:44: persistent_store: ERROR: Error in reading from store file

2018-05-02 10:30:44: persistent_store: ERROR: No JSON object could be decoded

I only changed DHCP scope, other than that cfg is default.

Cheers,
Luca

[rssluca]

I just did some more tests, it looks like this happens when i power cycle the pi (without proper shutdown)

`2018-05-03 12:40:00: #########################################################

2018-05-03 12:40:00: Starting the ZTP Service

● ztp.service - FreeZTP Service
Loaded: loaded (/etc/systemd/system/ztp.service; enabled; vendor preset: enabled)
Active: active (running) since Thu 2018-05-03 12:39:24 UTC; 36s ago
Main PID: 367 (bash)
CGroup: /system.slice/ztp.service
├─367 /bin/bash -c cd /bin; python ztp run
└─388 python ztp run

May 03 12:39:59 raspberrypi bash[367]: fulldb = self._pull_full_db() # Pull a full copy of the db
May 03 12:39:59 raspberrypi bash[367]: File "ztp", line 2327, in _pull_full_db
May 03 12:39:59 raspberrypi bash[367]: result = json.loads(rawdata)
May 03 12:39:59 raspberrypi bash[367]: File "/usr/lib/python2.7/json/init.py", line 339, in loads
May 03 12:39:59 raspberrypi bash[367]: return _default_decoder.decode(s)
May 03 12:39:59 raspberrypi bash[367]: File "/usr/lib/python2.7/json/decoder.py", line 364, in decode
May 03 12:39:59 raspberrypi bash[367]: obj, end = self.raw_decode(s, idx=_w(s, 0).end())
May 03 12:39:59 raspberrypi bash[367]: File "/usr/lib/python2.7/json/decoder.py", line 382, in raw_decode
May 03 12:39:59 raspberrypi bash[367]: raise ValueError("No JSON object could be decoded")
May 03 12:39:59 raspberrypi bash[367]: ValueError: No JSON object could be decoded
2018-05-03 12:40:00: #########################################################`

[PackeTsar]

Strange. Looks like something got corrupted in the db. Try deleting the db rm /etc/ztp/pdb and restart the service ztp service restart

[rssluca]

Done and all good, it does it every time the pi is not shutdown properly.

Also, new one after after provisioning first batch.

2018-05-03 14:41:01: persistent_store: ERROR: Error in reading from store file

2018-05-03 14:41:01: persistent_store: ERROR: Extra data: line 237 column 2 - line 249 column 2 (char 7879 - 8208)

2018-05-03 14:41:01: persistent_store: ERROR: Error in reading from store file

2018-05-03 14:41:01: persistent_store: ERROR: Extra data: line 237 column 2 - line 249 column 2 (char 7879 - 8208)

2018-05-03 14:41:01: persistent_store: ERROR: Error in reading from store file

2018-05-03 14:41:01: persistent_store: ERROR: Extra data: line 237 column 2 - line 249 column 2 (char 7879 - 8208)

Will do some more tshooting..

[PackeTsar]

Can you attach a sanitized copy of the pdb file here?

[PackeTsar]

And did the provisioning work OK?

[rssluca]

Already removed unfortunately. Will grab one if it happens again.

I added 6 switches then another 4 after 5 minutes.

The first batch did the upgrade, however, only 2 took the cfg, while the other did not (I am checking whether the hostname has changed to confirm the sw has been installed) the other 4 did not upgrade.

Will keep you posted.

[rssluca]

Ok, patched 8 together, 5 in json then same issue. It did push the new io to all of them though, just not all got the cfg. Json file attached.
pdb.txt

[PackeTsar]

yea I can see towards the bottom where the JSON file got screwed up. So what happens when they don't get their configs? Is it because the ZTP server crashes in the middle of provisioning?

[rssluca]

Not sure! Will do some more testing tomorrow and keep you posted.

Luca

[derek-shnosh]

Ran into the same thing today, everything was working fine and started seeing the following when running ztp show provisioning/dhcp leases/downloads;

$ ztp show provisioning 
10:54:38 -- Unable to log to logfile /etc/ztp/ztp.log. Make sure FreeZTP is installed. Disabling logging to logfile
10:54:38 -- 2018-09-18 10:54:45:   persistent_store: ERROR: Error in reading from store file
10:54:38 -- 
10:54:38 -- 2018-09-18 10:54:45:   persistent_store: ERROR: Extra data: line 12871 column 5 - line 12872 column 2 (char 453228 - 453231)
10:54:38 -- 
10:54:38 -- 2018-09-18 10:54:45:   persistent_store: ERROR: Error in reading from store file
10:54:38 -- 
10:54:38 -- 2018-09-18 10:54:45:   persistent_store: ERROR: Extra data: line 12871 column 5 - line 12872 column 2 (char 453228 - 453231)
10:54:38 -- 
10:54:38 -- 2018-09-18 10:54:45:   persistent_store: ERROR: Error in reading from store file
10:54:38 -- 
10:54:38 -- 2018-09-18 10:54:45:   persistent_store: ERROR: Extra data: line 12871 column 5 - line 12872 column 2 (char 453228 - 453231)

I'm wondering if we hit some kind of line/size limit.

Anyways, resolved by backing up the pdb file and restarting ztp services.

mv /etc/ztp/pdb /etc/ztp/pdb.bak
ztp services restart

@PackeTsar, let me know if you want the pdb file for review.

[PackeTsar]

I have seen recurring reports of this issue. It may be related to how I am writing data to that file. Thinking that it may get corrupted due to multiple concurrent writes. I will look into this.

[PackeTsar]

Tracking this. Closing.