/data disk is full - Githubissues

mpvader commented 7 years ago

There is a ~100 MB sqlite3 file (sparse!? since size of /data is only 30MB). See more details below.

Checks already done:

vrmlogger interval is set to 60 seconds: OK.
though large on disk, the database is empty:
```
sqlite> select count(*) from queue;
0
```

Details:

2017-02-08 02:48:08.444946500 *** CCGX booted (1) ***
2017-02-08 02:48:35.044311500 MainThread-vrmlogger: /opt/victronenergy/vrmlogger/vrmlogger.py v2.65 is starting up
2017-02-08 02:48:35.059661500 MainThread-vrmlogger: Loglevel set to INFO
2017-02-08 02:48:35.116638500 MainThread-vedbus: registered ourselves on D-Bus as com.victronenergy.logger
2017-02-08 02:48:35.163208500 MainThread-dbusmonitor: ===== Search on dbus for services that we will monitor starting... =====
2017-02-08 02:48:35.197143500 MainThread-dbusmonitor: Found: com.victronenergy.system matches com.victronenergy.system, scanning and storing items
2017-02-08 02:48:35.215881500 MainThread-dbusmonitor:        com.victronenergy.system has device instance 0
2017-02-08 02:48:36.138122500 MainThread-dbusmonitor: Found: com.victronenergy.settings matches com.victronenergy.settings, scanning and storing items
2017-02-08 02:48:36.148162500 MainThread-dbusmonitor:        com.victronenergy.settings has device instance 0
2017-02-08 02:48:36.522705500 MainThread-dbusmonitor: ===== Search on dbus for services that we will monitor finished =====
2017-02-08 02:48:36.995300500 MainThread-kwhdeltas: no suitable battery service found
2017-02-08 02:48:37.179504500 MainThread-kwhdeltas: no suitable battery service found
2017-02-08 02:48:37.722656500 MainThread-vrmlogger: Starting to log, logmode == LogToVRM
2017-02-08 02:48:37.830780500 MainThread-http_endpoint: Internal backlog buffer initialised. Count = 43
2017-02-08 02:48:37.834411500 MainThread-http_endpoint: Found '' as remembered external path
2017-02-08 02:48:37.838378500 MainThread-http_endpoint: Checking '' for suitability for external storage
2017-02-08 02:48:37.841369500 MainThread-http_endpoint: Mount point to check was empty.
2017-02-08 02:48:37.844421500 MainThread-http_endpoint: Because we haven't found a suitable remembered external storage path, we're scanning for one to use.
2017-02-08 02:48:37.848937500 MainThread-http_endpoint: No mountpoint candidates found.
2017-02-08 02:48:37.852203500 MainThread-http_endpoint: No suitable external storage path found
2017-02-08 02:48:37.863281500 MainThread-http_endpoint: Starting sender thread
2017-02-08 02:48:37.913940500 MainThread-http_endpoint: Started sender thread
2017-02-08 02:48:37.928375500 MainThread-http_endpoint: HttpEndpoint initialised, http worker thread running
2017-02-08 02:48:37.934875500 MainThread-ve_utils: Error while reading /proc/device-tree/model: [Errno 2] No such file or directory: '/proc/device-tree/model'
2017-02-08 02:48:38.764312500 MainThread-vrmlogger: Starting mainloop, responding on only events
2017-02-08 02:49:15.481231500 MainThread-dbusmonitor: Found: com.victronenergy.solarcharger.ttyO0 matches com.victronenergy.solarcharger, scanning and storing items
2017-02-08 02:49:17.108825500 MainThread-dbusmonitor:        com.victronenergy.solarcharger.ttyO0 has device instance 256
2017-02-08 05:43:45.536682500 *** CCGX booted (1) ***
2017-02-08 05:44:12.269836500 MainThread-vrmlogger: /opt/victronenergy/vrmlogger/vrmlogger.py v2.65 is starting up
2017-02-08 05:44:12.277618500 MainThread-vrmlogger: Loglevel set to INFO
2017-02-08 05:44:12.343994500 MainThread-vedbus: registered ourselves on D-Bus as com.victronenergy.logger
2017-02-08 05:44:12.436584500 MainThread-dbusmonitor: ===== Search on dbus for services that we will monitor starting... =====
2017-02-08 05:44:12.436614500 MainThread-dbusmonitor: Found: com.victronenergy.system matches com.victronenergy.system, scanning and storing items
2017-02-08 05:44:12.453186500 MainThread-dbusmonitor:        com.victronenergy.system has device instance 0
2017-02-08 05:44:16.039886500 MainThread-dbusmonitor: Found: com.victronenergy.settings matches com.victronenergy.settings, scanning and storing items
2017-02-08 05:44:16.072570500 MainThread-dbusmonitor:        com.victronenergy.settings has device instance 0
2017-02-08 05:44:16.718048500 MainThread-dbusmonitor: ===== Search on dbus for services that we will monitor finished =====
2017-02-08 05:44:16.911804500 MainThread-kwhdeltas: no suitable battery service found
2017-02-08 05:44:16.937438500 MainThread-kwhdeltas: no suitable battery service found
2017-02-08 05:44:17.076354500 MainThread-vrmlogger: Starting to log, logmode == LogToVRM
2017-02-08 05:44:17.236175500 MainThread-http_endpoint: Internal backlog buffer initialised. Count = 52
2017-02-08 05:44:17.242401500 MainThread-http_endpoint: Found '' as remembered external path
2017-02-08 05:44:17.350555500 MainThread-http_endpoint: Checking '' for suitability for external storage
2017-02-08 05:44:17.420715500 MainThread-http_endpoint: Mount point to check was empty.
2017-02-08 05:44:17.475402500 MainThread-http_endpoint: Because we haven't found a suitable remembered external storage path, we're scanning for one to use.
2017-02-08 05:44:17.521575500 MainThread-http_endpoint: No mountpoint candidates found.
2017-02-08 05:44:17.524841500 MainThread-http_endpoint: No suitable external storage path found
2017-02-08 05:44:17.540252500 MainThread-http_endpoint: Starting sender thread
2017-02-08 05:44:17.611297500 MainThread-http_endpoint: Started sender thread
2017-02-08 05:44:17.617645500 MainThread-http_endpoint: HttpEndpoint initialised, http worker thread running
2017-02-08 05:44:17.624084500 MainThread-ve_utils: Error while reading /proc/device-tree/model: [Errno 2] No such file or directory: '/proc/device-tree/model'
2017-02-08 05:44:19.010772500 MainThread-vrmlogger: Starting mainloop, responding on only events
2017-02-08 05:44:54.352203500 MainThread-dbusmonitor: Found: com.victronenergy.solarcharger.ttyO0 matches com.victronenergy.solarcharger, scanning and storing items
2017-02-08 05:44:55.583343500 MainThread-dbusmonitor:        com.victronenergy.solarcharger.ttyO0 has device instance 256
2017-02-09 07:07:47.469451500 *** CCGX booted (1) ***
2017-02-09 07:08:14.268157500 MainThread-vrmlogger: /opt/victronenergy/vrmlogger/vrmlogger.py v2.65 is starting up
2017-02-09 07:08:14.275726500 MainThread-vrmlogger: Loglevel set to INFO
2017-02-09 07:08:14.340606500 MainThread-vedbus: registered ourselves on D-Bus as com.victronenergy.logger
2017-02-09 07:08:14.371002500 MainThread-dbusmonitor: ===== Search on dbus for services that we will monitor starting... =====
2017-02-09 07:08:14.381927500 MainThread-dbusmonitor: Found: com.victronenergy.system matches com.victronenergy.system, scanning and storing items
2017-02-09 07:08:14.405151500 MainThread-dbusmonitor:        com.victronenergy.system has device instance 0
2017-02-09 07:08:15.295928500 MainThread-dbusmonitor: Found: com.victronenergy.settings matches com.victronenergy.settings, scanning and storing items
2017-02-09 07:08:15.330780500 MainThread-dbusmonitor:        com.victronenergy.settings has device instance 0
2017-02-09 07:08:16.348724500 MainThread-dbusmonitor: ===== Search on dbus for services that we will monitor finished =====
2017-02-09 07:08:16.752075500 MainThread-kwhdeltas: no suitable battery service found
2017-02-09 07:08:16.801025500 MainThread-kwhdeltas: no suitable battery service found
2017-02-09 07:08:16.935241500 MainThread-vrmlogger: Starting to log, logmode == LogToVRM
2017-02-09 07:08:17.038787500 MainThread-http_endpoint: Internal backlog buffer initialised. Count = 61
2017-02-09 07:08:17.042266500 MainThread-http_endpoint: Found '' as remembered external path
2017-02-09 07:08:17.045288500 MainThread-http_endpoint: Checking '' for suitability for external storage
2017-02-09 07:08:17.048309500 MainThread-http_endpoint: Mount point to check was empty.
2017-02-09 07:08:17.051116500 MainThread-http_endpoint: Because we haven't found a suitable remembered external storage path, we're scanning for one to use.
2017-02-09 07:08:17.055755500 MainThread-http_endpoint: No mountpoint candidates found.
2017-02-09 07:08:17.058868500 MainThread-http_endpoint: No suitable external storage path found
2017-02-09 07:08:17.070281500 MainThread-http_endpoint: Starting sender thread
2017-02-09 07:08:17.124176500 MainThread-http_endpoint: Started sender thread
2017-02-09 07:08:17.134155500 MainThread-http_endpoint: HttpEndpoint initialised, http worker thread running
2017-02-09 07:08:17.144744500 MainThread-ve_utils: Error while reading /proc/device-tree/model: [Errno 2] No such file or directory: '/proc/device-tree/model'
2017-02-09 07:08:17.903350500 MainThread-vrmlogger: Starting mainloop, responding on only events
2017-02-09 07:08:54.442901500 MainThread-dbusmonitor: Found: com.victronenergy.solarcharger.ttyO0 matches com.victronenergy.solarcharger, scanning and storing items
2017-02-09 07:08:55.603027500 MainThread-dbusmonitor:        com.victronenergy.solarcharger.ttyO0 has device instance 256
2017-02-09 07:10:22.088012500 MainThread-nonvolatilequeue: Vacuuming /data/db/vrmlogger-backlog.sqlite3, because the db is empty
2017-02-09 07:18:41.832244500 MainThread-vrmlogger: /opt/victronenergy/vrmlogger/vrmlogger.py v2.65 is starting up
2017-02-09 07:18:41.842590500 MainThread-vrmlogger: Loglevel set to INFO
2017-02-09 07:18:41.907318500 MainThread-vedbus: registered ourselves on D-Bus as com.victronenergy.logger
2017-02-09 07:18:41.947174500 MainThread-dbusmonitor: ===== Search on dbus for services that we will monitor starting... =====
2017-02-09 07:18:41.957550500 MainThread-dbusmonitor: Found: com.victronenergy.system matches com.victronenergy.system, scanning and storing items
2017-02-09 07:18:41.994079500 MainThread-dbusmonitor:        com.victronenergy.system has device instance 0
2017-02-09 07:18:43.056427500 MainThread-dbusmonitor: Found: com.victronenergy.settings matches com.victronenergy.settings, scanning and storing items
2017-02-09 07:18:48.081817500 MainThread-dbusmonitor:        com.victronenergy.settings has device instance 0
2017-02-09 07:18:48.081817500 MainThread-dbusmonitor: ===== Search on dbus for services that we will monitor finished =====
2017-02-09 07:18:48.081817500 MainThread-kwhdeltas: no suitable battery service found
2017-02-09 07:18:48.081848500 MainThread-kwhdeltas: no suitable battery service found
2017-02-09 07:18:48.081848500 MainThread-vrmlogger: Starting to log, logmode == LogToVRM
2017-02-09 07:18:48.081848500 Traceback (most recent call last):
2017-02-09 07:18:48.083312500   File "/opt/victronenergy/vrmlogger/vrmlogger.py", line 577, in <module>
2017-02-09 07:18:48.083312500     main()
2017-02-09 07:18:48.083312500   File "/opt/victronenergy/vrmlogger/vrmlogger.py", line 563, in main
2017-02-09 07:18:48.083312500     start_logging()
2017-02-09 07:18:48.083312500   File "/opt/victronenergy/vrmlogger/vrmlogger.py", line 350, in start_logging
2017-02-09 07:18:48.083343500     update_error_state_f=lambda c: dbusservice.__setitem__('/Buffer/ErrorState', c)
2017-02-09 07:18:48.084655500   File "/opt/victronenergy/vrmlogger/http_endpoint.py", line 97, in __init__
2017-02-09 07:18:48.084655500     update_oldest_timestamp=self._update_oldest_timestamp_f)
2017-02-09 07:18:48.084686500   File "/opt/victronenergy/vrmlogger/nonvolatilequeue.py", line 35, in __init__
2017-02-09 07:18:48.084686500     self.open()
root@ccgx:/opt#

root@ccgx:/opt# df
Filesystem           1K-blocks      Used Available Use% Mounted on
ubi0:rootfs1            190680     96520     94160  51% /
none                    123144        72    123072   0% /dev
tmpfs                   123144       200    122944   0% /var/volatile
tmpfs                   123144         0    123144   0% /media/ram
ubi0:data                29032     29028         0 100% /data

root@ccgx:/data# ls -lR | grep '^-' | sort -k 5 -rn
-rw-r--r--    1 root     root     101176320 Feb  9 07:13 vrmlogger-backlog.sqlite3
-rw-r--r--    1 root     root       8643248 Feb  9 07:13 vrmlogger-backlog.sqlite3-journal
-rw-r--r--    1 root     root        102438 Feb  7 03:19 messages.2
-rw-r--r--    1 root     root        102431 Feb  7 03:28 messages.1
-rw-r--r--    1 root     root        102412 Feb  8 05:43 messages.0
-rw-r--r--    1 root     root         60265 Feb  9 07:18 messages
-rwxr--r--    1 root     root         48061 Feb  9 07:07 current
-rw-r--r--    1 root     root         23531 Jan  9 23:27 @4000000058741daa2b9f07c4.u
-rwxr--r--    1 root     root         18013 Feb  9 07:07 current
-rw-r--r--    1 root     root         11678 Feb  7 03:14 @4000000058993bbd318f669c.u
-rw-r--r--    1 root     root          8192 Jan  9 23:48 watchdog_processlist.txt
-rw-r--r--    1 root     root          7905 Feb  7 03:28 @4000000058993ed31d211994.u
-rw-r--r--    1 root     root          6943 Feb  7 03:28 @4000000058993ed138f62d1c.u
-rw-r--r--    1 root     root          6649 Feb  9 07:18 current
-rw-r--r--    1 root     root          6479 Feb  9 07:07 @40000000589c155004ed7b74.u
-rw-r--r--    1 root     root          6479 Feb  8 05:43 @40000000589ab01e176985cc.u
-rw-r--r--    1 root     root          6479 Feb  8 02:48 @40000000589a86f507243194.u
-rw-r--r--    1 root     root          6479 Feb  7 03:25 @4000000058993e1c0bc79e0c.u
-rw-r--r--    1 root     root          6479 Feb  7 03:19 @4000000058993cda0c922d84.u
-rw-r--r--    1 root     root          6429 Feb  9 07:08 @40000000589c17c0016baf84.u
-rw-r--r--    1 root     root          5789 Feb  7 03:28 @4000000058993ed300eb292c.u
-rw-r--r--    1 root     root          5404 Feb  7 03:25 @4000000058993e1a2b9a5c74.u
-rw-r--r--    1 root     root          5356 Feb  9 07:10 settings.xml
-rw-r--r--    1 root     root          5314 Feb  8 05:43 @40000000589ab02716ef0e3c.u
-rw-r--r--    1 root     root          5180 Feb  8 05:43 @40000000589ab05709ca2ffc.u
-rw-r--r--    1 root     root          5180 Feb  7 03:25 @4000000058993e452be6bb3c.u
-rw-r--r--    1 root     root          5180 Feb  7 03:19 @4000000058993ce30bd0f0c4.u
-rw-r--r--    1 root     root          5090 Feb  9 07:07 @40000000589c1587228ae734.u
-rw-r--r--    1 root     root          5090 Feb  7 03:25 @4000000058993e540e978ad4.u
-rw-r--r--    1 root     root          5090 Feb  7 03:19 @4000000058993cf5178b84ec.u
-rw-r--r--    1 root     root          5043 Jan  3 08:13 @40000000586b5e5c260ad694.u
-rw-r--r--    1 root     root          4915 Feb  9 07:07 @40000000589c154f01836da4.u
-rw-r--r--    1 root     root          4915 Feb  7 03:19 @4000000058993cd83458cb84.u
-rw-r--r--    1 root     root          4883 Feb  9 07:07 @40000000589c157901a47e7c.u
-rw-r--r--    1 root     root          4865 Feb  9 07:10 @40000000589c17be2ba7dd7c.u
-rw-r--r--    1 root     root          4788 Feb  9 07:13 @40000000589c17c9070ce8a4.u
-rw-r--r--    1 root     root          4704 Feb  9 07:13 @40000000589c17d93329a60c.u
-rw-r--r--    1 root     root          4682 Dec 28 02:22 @400000005863233437d933fc.u
-rw-r--r--    1 root     root          4557 Feb  9 07:10 @40000000589c17c000e51a64.u
-rw-r--r--    1 root     root          4426 Feb  8 05:43 @40000000589ab01c375a8a34.u
-rw-r--r--    1 root     root          4426 Feb  8 02:48 @40000000589a86f337fb2f34.u
-rw-r--r--    1 root     root          4376 Feb  9 07:19 current
-rw-r--r--    1 root     root          4158 Feb  7 03:28 @4000000058993ed23930dc8c.u
-rw-------    1 root     root          4096 Jan 19 11:26 data
-rw-------    1 root     root          4096 Jan 13 07:38 data
-rw-------    1 root     root          4096 Jan 13 03:28 data
-rw-------    1 root     root          4096 Feb  9 07:13 data
-rw-r--r--    1 root     root          3903 Feb  7 03:28 @4000000058993ed311e083e4.u
-rw-r--r--    1 root     root          3856 Feb  8 05:43 @40000000589ab01e0cae96f4.u
-rw-r--r--    1 root     root          3444 Feb  9 07:07 @40000000589c154f2ab54404.u
-rw-r--r--    1 root     root          3444 Feb  8 05:43 @40000000589ab01d3b0031d4.u
-rw-r--r--    1 root     root          3444 Feb  7 03:25 @4000000058993e1b31349c6c.u
-rw-r--r--    1 root     root          3436 Jan 19 10:52 689e197d06ba_inst_ttyO1_Interfaces_Mk2_Tunnel.rvsc
-rw-r--r--    1 root     root          3330 Jan 19 10:50 RemoteVEConfigSettings.rvsc
-rw-r--r--    1 root     root          3286 Feb  9 07:07 @40000000589c154f2bc8ee54.u
-rw-r--r--    1 root     root          3286 Feb  8 05:43 @40000000589ab01d34445154.u
-rw-r--r--    1 root     root          3236 Feb  7 03:19 @4000000058993cd934ea16d4.u
-rw-r--r--    1 root     root          3194 Feb  7 03:28 @4000000058993ed30d66fdfc.u
-rw-r--r--    1 root     root          3136 Feb  7 03:19 @4000000058993cd929280c84.u
-rw-r--r--    1 root     root          3131 Feb  7 03:25 @4000000058993e1b1e7c0614.u
-rw-r--r--    1 root     root          2886 Feb  8 02:48 @40000000589a872c20445e4c.u
-rw-r--r--    1 root     root          2884 Feb  9 07:10 @40000000589c17c00a5d57dc.u
-rw-r--r--    1 root     root          2874 Feb  9 07:10 @40000000589c17bf3669c964.u
-rw-r--r--    1 root     root          2859 Feb  7 03:28 @4000000058993ed3149fabb4.u
-rw-r--r--    1 root     root          2809 Feb  9 07:07 @40000000589c15500743db0c.u
-rw-r--r--    1 root     root          2809 Feb  8 05:43 @40000000589ab01e0bb663e4.u

root@ccgx:/opt# ./color-control/vrmlogger/vrmlogger.py 
MainThread-vrmlogger: ./color-control/vrmlogger/vrmlogger.py v2.65 is starting up
MainThread-vrmlogger: Loglevel set to INFO
MainThread-vedbus: registered ourselves on D-Bus as com.victronenergy.logger
MainThread-dbusmonitor: ===== Search on dbus for services that we will monitor starting... =====
MainThread-dbusmonitor: Found: com.victronenergy.system matches com.victronenergy.system, scanning and storing items
MainThread-dbusmonitor:        com.victronenergy.system has device instance 0
MainThread-dbusmonitor: Found: com.victronenergy.settings matches com.victronenergy.settings, scanning and storing items
MainThread-dbusmonitor:        com.victronenergy.settings has device instance 0
MainThread-dbusmonitor: Found: com.victronenergy.solarcharger.ttyO0 matches com.victronenergy.solarcharger, scanning and storing items
MainThread-dbusmonitor:        com.victronenergy.solarcharger.ttyO0 has device instance 256
MainThread-dbusmonitor: ===== Search on dbus for services that we will monitor finished =====
MainThread-kwhdeltas: no suitable battery service found
MainThread-kwhdeltas: no suitable battery service found
MainThread-vrmlogger: Starting to log, logmode == LogToVRM
Traceback (most recent call last):
  File "./color-control/vrmlogger/vrmlogger.py", line 577, in <module>
    main()
  File "./color-control/vrmlogger/vrmlogger.py", line 563, in main
    start_logging()
  File "./color-control/vrmlogger/vrmlogger.py", line 350, in start_logging
    update_error_state_f=lambda c: dbusservice.__setitem__('/Buffer/ErrorState', c)
  File "/opt/victronenergy/vrmlogger/http_endpoint.py", line 97, in __init__
    update_oldest_timestamp=self._update_oldest_timestamp_f)
  File "/opt/victronenergy/vrmlogger/nonvolatilequeue.py", line 35, in __init__
    self.open()
  File "/opt/victronenergy/vrmlogger/nonvolatilequeue.py", line 55, in open
    cursor.execute("SELECT name FROM sqlite_master WHERE type='table' AND name='queue';")
sqlite3.OperationalError: database or disk is full

mpvader commented 7 years ago

root@ccgx:/data/db# du -hs ./vrmlogger-backlog.sqlite3 
96.5M   ./vrmlogger-backlog.sqlite3
root@ccgx:/data/db# df
Filesystem           1K-blocks      Used Available Use% Mounted on
ubi0:rootfs1            190680     96656     94024  51% /
none                    123144        72    123072   0% /dev
tmpfs                   123144       204    122940   0% /var/volatile
tmpfs                   123144         0    123144   0% /media/ram
ubi0:data                29032     27200       340  99% /data

mpvader commented 7 years ago

the untouched original files: vrmlogger-backlog.zip

mpvader commented 7 years ago

after removing a few files, and restarting vrmlogger, it starts to log (because the internet connection is up now, which is wasn't before).

root@ccgx:/data/log# rm messages*
root@ccgx:/data/log# /opt/color-control/vrmlogger/vrmlogger.py -d
MainThread-vrmlogger: /opt/color-control/vrmlogger/vrmlogger.py v2.65 is starting up
MainThread-vrmlogger: Loglevel set to DEBUG
MainThread-vedbus: VeDbusTreeExport / has been created
MainThread-vedbus: registered ourselves on D-Bus as com.victronenergy.logger
MainThread-vedbus: VeDbusTreeExport /Vrm has been created
MainThread-vedbus: added /Vrm/TimeLastContact with start value None. Writeable is False
MainThread-vedbus: VeDbusTreeExport /Buffer has been created
MainThread-vedbus: added /Buffer/Count with start value None. Writeable is False
MainThread-vedbus: added /Buffer/OldestTimestamp with start value None. Writeable is False
MainThread-vedbus: added /Buffer/Location with start value 0. Writeable is False
MainThread-vedbus: added /Buffer/FreeDiskSpace with start value 0. Writeable is False
MainThread-vedbus: added /Buffer/ErrorState with start value 0. Writeable is False
MainThread-vedbus: VeDbusTreeExport /Storage has been created
MainThread-vedbus: added /Storage/MountState with start value 0. Writeable is True
MainThread-dbusmonitor: ===== Search on dbus for services that we will monitor starting... =====
MainThread-dbusmonitor: Found: com.victronenergy.system matches com.victronenergy.system, scanning and storing items
MainThread-dbusmonitor:        com.victronenergy.system has device instance 0
MainThread-dbusmonitor: Found: com.victronenergy.settings matches com.victronenergy.settings, scanning and storing items
MainThread-dbusmonitor:        com.victronenergy.settings has device instance 0
MainThread-dbusmonitor: Found: com.victronenergy.solarcharger.ttyO0 matches com.victronenergy.solarcharger, scanning and storing items
MainThread-dbusmonitor:        com.victronenergy.solarcharger.ttyO0 has device instance 256
MainThread-dbusmonitor: ===== Search on dbus for services that we will monitor finished =====
MainThread-settingsdevice: ===== Settings device init starting... =====
MainThread-settingsdevice: Setting /Settings/SystemSetup/AcInput1 found
MainThread-settingsdevice: Setting /Settings/SystemSetup/AcInput2 found
MainThread-settingsdevice: ===== Settings device init finished =====
MainThread-kwhdeltas: no suitable battery service found
MainThread-kwhdeltas: no suitable battery service found
MainThread-settingsdevice: ===== Settings device init starting... =====
MainThread-settingsdevice: Setting /Settings/Vrmlogger/Http/ProxyPort found
MainThread-settingsdevice: Setting /Settings/Vrmlogger/ExternalStorageDir found
MainThread-settingsdevice: Setting /Settings/Vrmlogger/Url found
MainThread-settingsdevice: Setting /Settings/Vrmlogger/LogInterval found
MainThread-settingsdevice: Setting /Settings/Vrmlogger/Http/Proxy found
MainThread-settingsdevice: Setting /Settings/Vrmlogger/Logmode found
MainThread-settingsdevice: ===== Settings device init finished =====
MainThread-vrmlogger: Starting to log, logmode == LogToVRM
MainThread-http_endpoint: Internal backlog buffer initialised. Count = 0
MainThread-http_endpoint: Found '' as remembered external path
MainThread-http_endpoint: Checking '' for suitability for external storage
MainThread-http_endpoint: Mount point to check was empty.
MainThread-http_endpoint: Because we haven't found a suitable remembered external storage path, we're scanning for one to use.
MainThread-http_endpoint: No mountpoint candidates found.
MainThread-http_endpoint: No suitable external storage path found
MainThread-http_endpoint: Starting sender thread
MainThread-http_endpoint: Started sender thread
MainThread-http_endpoint: HttpEndpoint initialised, http worker thread running
MainThread-ve_utils: Error while reading /proc/device-tree/model: [Errno 2] No such file or directory: '/proc/device-tree/model'
HTTPThread-http_endpoint: Bulk of 1 to be sent
HTTPThread-http_endpoint: Bulk compressed size: 102, crc32: 1642396714
MainThread-vrmlogger: Starting mainloop, responding on only events
HTTPThread-http_endpoint: Result of bulk transmission: True
MainThread-http_endpoint: Processing job results (removing or storing in non-volatile queue, depending on result)
HTTPThread-http_endpoint: Bulk of 1 to be sent
HTTPThread-http_endpoint: Bulk compressed size: 220, crc32: 553684379
HTTPThread-http_endpoint: Result of bulk transmission: True
MainThread-http_endpoint: Processing job results (removing or storing in non-volatile queue, depending on result)
HTTPThread-http_endpoint: Bulk of 1 to be sent
HTTPThread-http_endpoint: Bulk compressed size: 231, crc32: 2268583694
HTTPThread-http_endpoint: Result of bulk transmission: True
MainThread-http_endpoint: Processing job results (removing or storing in non-volatile queue, depending on result)
HTTPThread-http_endpoint: Bulk of 1 to be sent
HTTPThread-http_endpoint: Bulk compressed size: 226, crc32: 537193484
HTTPThread-http_endpoint: Result of bulk transmission: True
MainThread-http_endpoint: Processing job results (removing or storing in non-volatile queue, depending on result)
HTTPThread-http_endpoint: Bulk of 1 to be sent
HTTPThread-http_endpoint: Bulk compressed size: 221, crc32: 1372517660
HTTPThread-http_endpoint: Result of bulk transmission: True
MainThread-http_endpoint: Processing job results (removing or storing in non-volatile queue, depending on result)
HTTPThread-http_endpoint: Bulk of 1 to be sent
HTTPThread-http_endpoint: Bulk compressed size: 220, crc32: 2462316728
HTTPThread-http_endpoint: Result of bulk transmission: True
MainThread-http_endpoint: Processing job results (removing or storing in non-volatile queue, depending on result)
HTTPThread-http_endpoint: Bulk of 1 to be sent
HTTPThread-http_endpoint: Bulk compressed size: 224, crc32: 2554405088
HTTPThread-http_endpoint: Result of bulk transmission: True
MainThread-http_endpoint: Processing job results (removing or storing in non-volatile queue, depending on result)
HTTPThread-http_endpoint: Bulk of 1 to be sent
HTTPThread-http_endpoint: Bulk compressed size: 224, crc32: 3673827095
HTTPThread-http_endpoint: Result of bulk transmission: True
MainThread-http_endpoint: Processing job results (removing or storing in non-volatile queue, depending on result)
HTTPThread-http_endpoint: Bulk of 1 to be sent
HTTPThread-http_endpoint: Bulk compressed size: 224, crc32: 2241379560
HTTPThread-http_endpoint: Result of bulk transmission: True

mpvader commented 7 years ago

Around 7:18, the device restarted:

2017-02-09 07:07:47.192199500 *** CCGX booted (1) ***
2017-02-09 07:08:00.942413500 -------- dbus_systemcalc, v1.36 is starting up --------
2017-02-09 07:08:00.959075500 INFO:logger:Loglevel set to INFO
2017-02-09 07:08:01.017242500 INFO:dbusmonitor:===== Search on dbus for services that we will monitor starting... =====
2017-02-09 07:08:01.045074500 INFO:dbusmonitor:===== Search on dbus for services that we will monitor finished =====
2017-02-09 07:08:01.120727500 INFO:settingsdevice:waiting for settings
2017-02-09 07:08:02.164642500 INFO:settingsdevice:waiting for settings
2017-02-09 07:08:03.209075500 INFO:settingsdevice:waiting for settings
2017-02-09 07:08:04.508605500 INFO:vedbus:registered ourselves on D-Bus as com.victronenergy.system
2017-02-09 07:08:04.816802500 INFO:delegates:Relays found: /sys/class/gpio/gpio182/value
2017-02-09 07:08:05.016967500 INFO:delegates:Buzzer found: /sys/class/gpio/gpio35/value
2017-02-09 07:08:06.655761500 INFO:dbus_systemcalc:Battery service initialized to None (setting == default)
2017-02-09 07:08:06.763793500 INFO:dbus_systemcalc:Starting mainloop, responding only on events
2017-02-09 07:08:07.833709500 INFO:dbusmonitor:Found: com.victronenergy.settings matches com.victronenergy.settings, scanning and storing items
2017-02-09 07:08:08.197570500 INFO:dbusmonitor:       com.victronenergy.settings has device instance 0
2017-02-09 07:08:53.428009500 INFO:dbusmonitor:Found: com.victronenergy.solarcharger.ttyO0 matches com.victronenergy.solarcharger, scanning and storing items
2017-02-09 07:08:53.912567500 INFO:dbusmonitor:       com.victronenergy.solarcharger.ttyO0 has device instance 256
2017-02-09 07:18:26.931274500 -------- dbus_systemcalc, v1.36 is starting up --------
2017-02-09 07:18:26.955413500 INFO:logger:Loglevel set to INFO
2017-02-09 07:18:26.999298500 INFO:dbusmonitor:===== Search on dbus for services that we will monitor starting... =====
2017-02-09 07:18:27.037139500 INFO:dbusmonitor:===== Search on dbus for services that we will monitor finished =====
2017-02-09 07:18:27.054290500 INFO:settingsdevice:waiting for settings
2017-02-09 07:18:28.063323500 INFO:settingsdevice:waiting for settings
2017-02-09 07:18:29.135803500 INFO:settingsdevice:waiting for settings
2017-02-09 07:18:30.086761500 INFO:settingsdevice:waiting for settings
2017-02-09 07:18:32.183624500 INFO:vedbus:registered ourselves on D-Bus as com.victronenergy.system
2017-02-09 07:18:33.906524500 INFO:delegates:Relays found: /sys/class/gpio/gpio182/value
2017-02-09 07:18:33.906555500 INFO:delegates:Buzzer found: /sys/class/gpio/gpio35/value
2017-02-09 07:18:33.906555500 INFO:dbus_systemcalc:Battery service initialized to None (setting == default)
2017-02-09 07:18:34.016265500 INFO:dbus_systemcalc:Starting mainloop, responding only on events
2017-02-09 07:18:36.330780500 INFO:dbusmonitor:Found: com.victronenergy.settings matches com.victronenergy.settings, scanning and storing items
2017-02-09 07:18:36.507690500 INFO:dbusmonitor:       com.victronenergy.settings has device instance 0
2017-02-09 07:19:18.610626500 INFO:dbusmonitor:Found: com.victronenergy.solarcharger.ttyO0 matches com.victronenergy.solarcharger, scanning and storing items
2017-02-09 08:01:16.583881500 INFO:dbusmonitor:       com.victronenergy.solarcharger.ttyO0 has device instance 256
root@ccgx:/data/db# uptime
 08:30:09 up  1:12,  load average: 0.26, 0.21, 0.28
root@ccgx:/data/db# date
Thu Feb  9 08:30:15 UTC 2017

mpvader commented 7 years ago

Reducing sqlite file size is done with the VACUUM command. Which is done by vrmlogger after successfully sending out the last item in the buffer.

The problem is reproducable on this particular ccgx (as long as none deletes that large SQLite file...):

I removed a few files (/data/log/messages*) to get vrmlogger up and running again and see what it did.
Manually started vrmlogger, which successfully opened the sqlite file, which removed the journal, but did obviously not VACUUM the main file.
Then internet was removed
CCGX Restarted
Then apparently there was a moment without Internet, putting some records in the file again
Then internet was restored, all files sent, VACUUM command issued again
Same 8 MB large journal file was created again
Stuck

wiebeytec commented 7 years ago

I found part of the problem. There is a system in place to protect filling the /data with the sqlite file: it should stop after less than 1 MB is available. I just confirmed the defacto recommended way of obtaining the free disk space in python (using os.statvfs) fails on Color Controls; it reports far too much. This is likely related to UBI.

I will look into a fix for obtaining the free space.

Then about the inability to vacuum. I vacuumed the sqlite file, and captured the journal file before it got deleted, with:

for fijl in $(inotifywait -e create . |awk '{ print $3 }'); do ln $fijl $fijl-linked; done

On my PC, this generates a 4k file. On a color control, this generates a 97.3MB file. I'll look into what kind of journal it uses under what conditions (write-ahead or rollback).

wiebeytec commented 7 years ago

My comment about measuring disk use was an error; it's correct after all. Because of a copy-paste mistake, my test script produced the wrong result.

That means the ultimate cause is the vacuum. I resolved it by disabling the journal for the vacuum (vacuum only happens when the DB is empty).

mpvader commented 7 years ago

Fixed in vrmlogger v2.67, which will be part of Venus 2.03.

wiebeytec commented 7 years ago

With disabling the journal, one can raise concern about db corruption. I would like to add that I tried several variations of the following command to try to corrupt a database that is being vacuumed:

inotifywait -e MODIFY . ; ls /tmp/fake_sleep ; kill -9 994

What this does, is issue a kill-9 command as soon as the vacuum started. I was able to kill it at several stages, before and after the vacuum succeeded. Nothing resulted in a corrupt file.

victronenergy / venus

/data disk is full #126