I have been debugging a problem with a perfsonar node. It was
installed last year, but has been updated to 4.1.4
Looking at it now, I find that tests are running (e.g. tcpdump
shows the UDP owamp). The problem is that even though all
services are green / running, nothing is shown under "Test
Results" in the GUI.
The node is NTP-synced and has plenty of disk space. "yum
upgrade" says there's nothing to upgrade, and the node was
rebooted yesterday.
$ uptime
08:37:39 up 20:01, 2 users, load average: 0.08, 0.10, 0.13
I turned on debugging using:
sudo pscheduler debug on scheduler
sudo pscheduler debug on runner
sudo pscheduler debug on archiver
At the end of this mail I have posted 50 lines of
/var/log/pscheduler/pscheduler.log. I don't see any errors, and
as far as I can tell, it's showing successful archiving of data.
e.g.
Dec 14 08:31:23 perfsonar-border journal: archiver DEBUG
277726: Archiving to esmond: {...}
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG 277726: Returned JSON from archiver: {u'succeeded':
True}
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG 277726: Succeeded: 082a8a17-4a75-4d99-a2f0-b413e562e4fb
to esmond
If I look in log files under /var/log/perfsonar/, things start to
get interesting.
$ ls
clean_esmond_db.log lscachedaemon.log.5
lsregistrationdaemon.log.4 owamp_bwctl.log-20180107
psconfig-pscheduler-agent.log
configdaemon.log lscachedaemon.log.6
lsregistrationdaemon.log.5 owamp_bwctl.log-20180122
psconfig-pscheduler-agent-tasks.log
lscachedaemon.log lscachedaemon.log.7
lsregistrationdaemon.log.6 owamp_bwctl.log-20180207
psconfig-pscheduler-agent-transactions.log
lscachedaemon.log.1 lsregistrationdaemon.log
lsregistrationdaemon.log.7 owamp_bwctl.log-20181213
psconfig-pscheduler-migrate.log
lscachedaemon.log.2 lsregistrationdaemon.log.1
meshconfig-agent.log owamp.log
servicewatcher_error.log
lscachedaemon.log.3 lsregistrationdaemon.log.2
oppd-server.log psb_to_esmond.log web_admin
lscachedaemon.log.4 lsregistrationdaemon.log.3
owamp_bwctl.log pscheduler.log
$ ls -l clean_esmond_db.log
-rw-r--r-- 1 perfsonar perfsonar 444 Dec 14 02:30
clean_esmond_db.log
$ cat clean_esmond_db.log
Connection error: Could not connect to localhost:9160
Connection error: Could not connect to localhost:9160
Connection error: Could not connect to localhost:9160
Traceback (most recent call last):
File "./util/ps_remove_data.py", line 96, in
<module>
from esmond.api.perfsonar.api_v2 import
EVENT_TYPE_CF_MAP
ImportError: cannot import name EVENT_TYPE_CF_MAP
Failed to connect to '127.0.0.1:7199': Connection refused
(Connection refused)
$ tail -5 owamp.log
Dec 14 07:55:09 perfsonar-border bwctld[2387]:
FILE=sapi.c, LINE=391, BWLControlAccept(): Unable to read
ClientGreeting message
Dec 14 07:55:13 perfsonar-border bwctld[2396]:
FILE=sapi.c, LINE=391, BWLControlAccept(): Unable to read
ClientGreeting message
Dec 14 07:55:14 perfsonar-border bwctld[2445]:
FILE=sapi.c, LINE=391, BWLControlAccept(): Unable to read
ClientGreeting message
Dec 14 07:55:17 perfsonar-border bwctld[2638]:
FILE=sapi.c, LINE=391, BWLControlAccept(): Unable to read
ClientGreeting message
Dec 14 07:55:18 perfsonar-border bwctld[2657]:
FILE=sapi.c, LINE=391, BWLControlAccept(): Unable to read
ClientGreeting message
The error about esmond cleaner having connection refused looks
bad. The bwctl errors are probably spurious, given that this node
is using pscheduler.
OK, so now /var/log/esmond.
$ ls -l
total 37716
drwxr-xr-x. 2 apache apache 6 Jun 13 2017 crashlog
-rw-r--r-- 1 apache apache 3522030 Dec 14 08:42
django.log
-rw-r--r-- 1 apache apache 5240865 Dec 14 06:01
django.log.1
-rw-r--r-- 1 apache apache 5240865 Dec 14 02:03
django.log.2
-rw-r--r-- 1 apache apache 5240865 Dec 13 22:04
django.log.3
-rw-r--r-- 1 apache apache 5240889 Dec 13 18:06
django.log.4
-rw-r--r-- 1 apache apache 5240865 Feb 9 2018
django.log.5
-rw-r--r--. 1 apache apache 3214412 Dec 13 14:38
esmond.log
-rw-r--r--. 1 apache apache 5242756 Sep 17 2017
esmond.log.1
-rw-r--r--. 1 apache apache 1260 Dec 13 14:38
install.log
Oddly, esmond.log has a timestamp of Dec 13, but it contains only
old messages from January.
$ tail -5 esmond.log
2018-01-02 22:56:02,276 [ERROR]
/usr/lib/esmond/esmond/api/perfsonar/api_v2.py: Unable to
connect to cassandra. Please verify cassandra is running.
2018-01-02 22:56:02,339 [ERROR]
/usr/lib/esmond/esmond/api/perfsonar/api_v2.py: Unable to
connect to cassandra. Please verify cassandra is running.
2018-01-02 22:56:02,342 [ERROR]
/usr/lib/esmond/esmond/api/perfsonar/api_v2.py: Unable to
connect to cassandra. Please verify cassandra is running.
2018-01-02 22:56:19,475 [ERROR]
/usr/lib/esmond/esmond/api/perfsonar/api_v2.py: Unable to
connect to cassandra. Please verify cassandra is running.
2018-01-02 22:56:19,477 [ERROR]
/usr/lib/esmond/esmond/api/perfsonar/api_v2.py: Unable to
connect to cassandra. Please verify cassandra is running.
django.log shows a similar error, but this is from this morning:
$ tail -30 django.log
File "/usr/lib/esmond/esmond/cassandra.py", line 134,
in __init__
"at %s - %s" % (config.cassandra_servers[0], e))
ConnectionException: "System Manager can't connect to
Cassandra at localhost:9160 - Could not connect to
localhost:9160"
2018-12-14 08:43:37,464 [ERROR]
/usr/lib/esmond/lib/python2.7/site-packages/django/core/handlers/exception.py:
Internal Server Error:
/esmond/perfsonar/archive/97b1925a9eee46b5aec7d823db5e902b/
Traceback (most recent call last):
File
"/usr/lib/esmond/lib/python2.7/site-packages/django/core/handlers/exception.py",
line 42, in inner
response = get_response(request)
File
"/usr/lib/esmond/lib/python2.7/site-packages/django/core/handlers/base.py",
line 249, in _legacy_get_response
response = self._get_response(request)
File
"/usr/lib/esmond/lib/python2.7/site-packages/django/core/handlers/base.py",
line 187, in _get_response
response = self.process_exception_by_middleware(e,
request)
File
"/usr/lib/esmond/lib/python2.7/site-packages/django/core/handlers/base.py",
line 185, in _get_response
response = wrapped_callback(request, *callback_args,
**callback_kwargs)
File
"/usr/lib/esmond/lib/python2.7/site-packages/django/views/decorators/csrf.py",
line 58, in wrapped_view
return view_func(*args, **kwargs)
File
"/usr/lib/esmond/lib/python2.7/site-packages/rest_framework/viewsets.py",
line 90, in view
return self.dispatch(request, *args, **kwargs)
File
"/usr/lib/esmond/lib/python2.7/site-packages/rest_framework/views.py",
line 489, in dispatch
response = self.handle_exception(exc)
File
"/usr/lib/esmond/lib/python2.7/site-packages/rest_framework/views.py",
line 449, in handle_exception
self.raise_uncaught_exception(exc)
File
"/usr/lib/esmond/lib/python2.7/site-packages/rest_framework/views.py",
line 486, in dispatch
response = handler(request, *args, **kwargs)
File "/usr/lib/esmond/esmond/api/perfsonar/api_v2.py",
line 887, in update
check_connection()
File "/usr/lib/esmond/esmond/api/perfsonar/api_v2.py",
line 78, in check_connection
db = CASSANDRA_DB(get_config(get_config_path()))
File "/usr/lib/esmond/esmond/cassandra.py", line 134,
in __init__
"at %s - %s" % (config.cassandra_servers[0], e))
ConnectionException: "System Manager can't connect to
Cassandra at localhost:9160 - Could not connect to
localhost:9160"
Looks like a problem with cassandra. So on to /var/log/cassandra
$ ls -l
total 27960
-rw-r--r--. 1 root root 13489 Dec 14 08:00
cassandra.log
-rw-r--r-- 1 cassandra cassandra 7630130 Dec 14 08:00
system.log
-rw-r--r--. 1 cassandra cassandra 20971761 Oct 9 2017
system.log.1
$ cat cassandra.log
INFO 08:00:13,998 Logging initialized
INFO 08:00:14,399 Loading settings from
file:/etc/cassandra/default.conf/cassandra.yaml
INFO 08:00:14,798 Data files directories:
[/var/lib/cassandra/data]
INFO 08:00:14,893 Commit log directory:
/var/lib/cassandra/commitlog
INFO 08:00:14,894 DiskAccessMode 'auto' determined to be mmap,
indexAccessMode is mmap
INFO 08:00:14,894 disk_failure_policy is stop
INFO 08:00:14,894 commit_failure_policy is stop
INFO 08:00:14,927 Global memtable threshold is enabled at 214MB
INFO 08:00:15,295 Not using multi-threaded compaction
INFO 08:00:15,995 Loading settings from
file:/etc/cassandra/default.conf/cassandra.yaml
INFO 08:00:16,029 Loading settings from
file:/etc/cassandra/default.conf/cassandra.yaml
INFO 08:00:16,048 JVM vendor/version: OpenJDK 64-Bit Server
VM/1.7.0_201
WARN 08:00:16,048 OpenJDK is not recommended. Please upgrade to
the newest Oracle Java release
INFO 08:00:16,049 Heap size: 899678208/899678208
INFO 08:00:16,049 Code Cache Non-heap memory: init =
2555904(2496K) used = 638208(623K) committed = 2555904(2496K)
max = 50331648(49152K)
INFO 08:00:16,049 Par Eden Space Heap memory: init =
184549376(180224K) used = 59234552(57846K) committed =
184549376(180224K) max = 184549376(180224K)
INFO 08:00:16,052 Par Survivor Space Heap memory: init =
23068672(22528K) used = 0(0K) committed = 23068672(22528K) max =
23068672(22528K)
INFO 08:00:16,052 CMS Old Gen Heap memory: init =
692060160(675840K) used = 0(0K) committed = 692060160(675840K)
max = 692060160(675840K)
INFO 08:00:16,052 CMS Perm Gen Non-heap memory: init =
21757952(21248K) used = 14193144(13860K) committed =
21757952(21248K) max = 174063616(169984K)
INFO 08:00:16,052 Classpath:
/etc/cassandra/conf:/usr/share/cassandra/lib/antlr-3.2.jar:/usr/share/cassandra/lib/apache-cassandra-2.0.17.jar:/usr/share/cassandra/lib/apache-cassandra-clientutil-2.0.17.jar:/usr/share/cassandra/lib/apache-cassandra-thrift-2.0.17.jar:/usr/share/cassandra/lib/commons-cli-1.1.jar:/usr/share/cassandra/lib/commons-codec-1.2.jar:/usr/share/cassandra/lib/commons-lang3-3.1.jar:/usr/share/cassandra/lib/compress-lzf-0.8.4.jar:/usr/share/cassandra/lib/concurrentlinkedhashmap-lru-1.3.jar:/usr/share/cassandra/lib/disruptor-3.0.1.jar:/usr/share/cassandra/lib/guava-15.0.jar:/usr/share/cassandra/lib/high-scale-lib-1.1.2.jar:/usr/share/cassandra/lib/jackson-core-asl-1.9.2.jar:/usr/share/cassandra/lib/jackson-mapper-asl-1.9.2.jar:/usr/share/cassandra/lib/jamm-0.2.5.jar:/usr/share/cassandra/lib/jbcrypt-0.3m.jar:/usr/share/cassandra/lib/jline-1.0.jar:/usr/share/cassandra/lib/json-simple-1.1.jar:/usr/share/cassandra/lib/libthrift-0.9.1.jar:/usr/share/cassandra/lib/log4j-1.2.16.jar:/usr/share/cassandra/lib/lz4-1.2.0.jar:/usr/share/cassandra/lib/metrics-core-2.2.0.jar:/usr/share/cassandra/lib/netty-3.6.6.Final.jar:/usr/share/cassandra/lib/reporter-config-2.1.0.jar:/usr/share/cassandra/lib/servlet-api-2.5-20081211.jar:/usr/share/cassandra/lib/slf4j-api-1.7.2.jar:/usr/share/cassandra/lib/slf4j-log4j12-1.7.2.jar:/usr/share/cassandra/lib/snakeyaml-1.11.jar:/usr/share/cassandra/lib/snappy-java-1.0.5.jar:/usr/share/cassandra/lib/snaptree-0.1.jar:/usr/share/cassandra/lib/stress.jar:/usr/share/cassandra/lib/super-csv-2.1.0.jar:/usr/share/cassandra/lib/thrift-server-0.3.7.jar:/usr/share/cassandra/lib/jamm-0.2.5.jar
INFO 08:00:16,057 JNA not found. Native methods will be
disabled.
WARN 08:00:16,058 JMX is not enabled to receive remote
connections. Please see cassandra-env.sh for more info.
INFO 08:00:16,544 Initializing key cache with capacity of 42
MBs.
INFO 08:00:16,576 Scheduling key cache save to each 14400
seconds (going to save all keys).
INFO 08:00:16,577 Initializing row cache with capacity of 0 MBs
INFO 08:00:16,600 Scheduling row cache save to each 0 seconds
(going to save all keys).
INFO 08:00:16,847 Initializing system.schema_triggers
INFO 08:00:16,878 Initializing system.compaction_history
INFO 08:00:16,885 Opening
/var/lib/cassandra/data/system/compaction_history/system-compaction_history-jb-167
(8910 bytes)
INFO 08:00:16,885 Opening
/var/lib/cassandra/data/system/compaction_history/system-compaction_history-jb-169
(247 bytes)
INFO 08:00:16,885 Opening
/var/lib/cassandra/data/system/compaction_history/system-compaction_history-jb-168
(249 bytes)
INFO 08:00:17,071 Initializing system.batchlog
INFO 08:00:17,080 Initializing system.sstable_activity
INFO 08:00:17,082 Opening
/var/lib/cassandra/data/system/sstable_activity/system-sstable_activity-jb-394
(231 bytes)
INFO 08:00:17,082 Opening
/var/lib/cassandra/data/system/sstable_activity/system-sstable_activity-jb-393
(231 bytes)
INFO 08:00:17,137 Initializing system.peer_events
INFO 08:00:17,145 Initializing system.compactions_in_progress
INFO 08:00:17,152 Initializing system.hints
INFO 08:00:17,161 Initializing system.schema_keyspaces
INFO 08:00:17,163 Opening
/var/lib/cassandra/data/system/schema_keyspaces/system-schema_keyspaces-jb-13
(256 bytes)
INFO 08:00:17,163 Opening
/var/lib/cassandra/data/system/schema_keyspaces/system-schema_keyspaces-jb-14
(135 bytes)
INFO 08:00:17,257 Initializing system.range_xfers
INFO 08:00:17,266 Initializing system.schema_columnfamilies
INFO 08:00:17,269 Opening
/var/lib/cassandra/data/system/schema_columnfamilies/system-schema_columnfamilies-jb-13
(7605 bytes)
INFO 08:00:17,269 Opening
/var/lib/cassandra/data/system/schema_columnfamilies/system-schema_columnfamilies-jb-14
(7604 bytes)
INFO 08:00:17,269 Opening
/var/lib/cassandra/data/system/schema_columnfamilies/system-schema_columnfamilies-jb-15
(7601 bytes)
INFO 08:00:17,313 reading saved cache
/var/lib/cassandra/saved_caches/system-schema_columnfamilies-KeyCache-b.db
INFO 08:00:17,345 Initializing system.NodeIdInfo
INFO 08:00:17,347 Opening
/var/lib/cassandra/data/system/NodeIdInfo/system-NodeIdInfo-jb-1
(62 bytes)
INFO 08:00:17,353 reading saved cache
/var/lib/cassandra/saved_caches/system-NodeIdInfo-KeyCache-b.db
INFO 08:00:17,372 Initializing system.paxos
INFO 08:00:17,382 Initializing system.schema_columns
INFO 08:00:17,384 Opening
/var/lib/cassandra/data/system/schema_columns/system-schema_columns-jb-13
(12265 bytes)
INFO 08:00:17,385 Opening
/var/lib/cassandra/data/system/schema_columns/system-schema_columns-jb-14
(11972 bytes)
INFO 08:00:17,384 Opening
/var/lib/cassandra/data/system/schema_columns/system-schema_columns-jb-15
(11985 bytes)
INFO 08:00:17,498 reading saved cache
/var/lib/cassandra/saved_caches/system-schema_columns-KeyCache-b.db
INFO 08:00:17,527 Initializing system.IndexInfo
INFO 08:00:17,534 Initializing system.peers
INFO 08:00:17,543 Initializing system.local
INFO 08:00:17,547 Opening
/var/lib/cassandra/data/system/local/system-local-jb-39 (5262
bytes)
INFO 08:00:17,547 Opening
/var/lib/cassandra/data/system/local/system-local-jb-40 (139
bytes)
INFO 08:00:17,547 Opening
/var/lib/cassandra/data/system/local/system-local-jb-37 (5752
bytes)
INFO 08:00:17,547 Opening
/var/lib/cassandra/data/system/local/system-local-jb-38 (116
bytes)
INFO 08:00:17,627 reading saved cache
/var/lib/cassandra/saved_caches/system-local-KeyCache-b.db
ERROR 08:00:17,797 Exception encountered during startup
org.apache.cassandra.io.sstable.CorruptSSTableException:
org.apache.cassandra.io.compress.CorruptBlockException:
(/var/lib/cassandra/data/system/local/system-local-jb-40-Data.db):
corruption detected, chunk at 0 of length 135.
at
org.apache.cassandra.io.compress.CompressedRandomAccessReader.reBuffer(CompressedRandomAccessReader.java:91)
at
org.apache.cassandra.io.util.RandomAccessReader.seek(RandomAccessReader.java:283)
at
org.apache.cassandra.io.util.PoolingSegmentedFile.getSegment(PoolingSegmentedFile.java:41)
at
org.apache.cassandra.io.sstable.SSTableReader.getFileDataInput(SSTableReader.java:1284)
at
org.apache.cassandra.db.columniterator.SimpleSliceReader.<init>(SimpleSliceReader.java:57)
at
org.apache.cassandra.db.columniterator.SSTableSliceIterator.createReader(SSTableSliceIterator.java:65)
at
org.apache.cassandra.db.columniterator.SSTableSliceIterator.<init>(SSTableSliceIterator.java:42)
at
org.apache.cassandra.db.filter.SliceQueryFilter.getSSTableColumnIterator(SliceQueryFilter.java:238)
at
org.apache.cassandra.db.filter.QueryFilter.getSSTableColumnIterator(QueryFilter.java:62)
at
org.apache.cassandra.db.CollationController.collectAllData(CollationController.java:250)
at
org.apache.cassandra.db.CollationController.getTopLevelColumns(CollationController.java:53)
at
org.apache.cassandra.db.ColumnFamilyStore.getTopLevelColumns(ColumnFamilyStore.java:1619)
at
org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore.java:1438)
at
org.apache.cassandra.db.Keyspace.getRow(Keyspace.java:340)
at
org.apache.cassandra.db.SliceFromReadCommand.getRow(SliceFromReadCommand.java:89)
at
org.apache.cassandra.cql3.statements.SelectStatement.readLocally(SelectStatement.java:318)
at
org.apache.cassandra.cql3.statements.SelectStatement.executeInternal(SelectStatement.java:338)
at
org.apache.cassandra.cql3.statements.SelectStatement.executeInternal(SelectStatement.java:67)
at
org.apache.cassandra.cql3.QueryProcessor.processInternal(QueryProcessor.java:208)
at
org.apache.cassandra.db.SystemKeyspace.checkHealth(SystemKeyspace.java:559)
at
org.apache.cassandra.service.CassandraDaemon.setup(CassandraDaemon.java:320)
at
org.apache.cassandra.service.CassandraDaemon.activate(CassandraDaemon.java:554)
at
org.apache.cassandra.service.CassandraDaemon.main(CassandraDaemon.java:643)
Caused by:
org.apache.cassandra.io.compress.CorruptBlockException:
(/var/lib/cassandra/data/system/local/system-local-jb-40-Data.db):
corruption detected, chunk at 0 of length 135.
at
org.apache.cassandra.io.compress.CompressedRandomAccessReader.decompressChunk(CompressedRandomAccessReader.java:122)
at
org.apache.cassandra.io.compress.CompressedRandomAccessReader.reBuffer(CompressedRandomAccessReader.java:87)
... 22 more
Caused by: java.io.IOException: Compressed lengths mismatch
at
org.apache.cassandra.io.compress.LZ4Compressor.uncompress(LZ4Compressor.java:98)
at
org.apache.cassandra.io.compress.CompressedRandomAccessReader.decompressChunk(CompressedRandomAccessReader.java:118)
... 23 more
org.apache.cassandra.io.sstable.CorruptSSTableException:
org.apache.cassandra.io.compress.CorruptBlockException:
(/var/lib/cassandra/data/system/local/system-local-jb-40-Data.db):
corruption detected, chunk at 0 of length 135.
at
org.apache.cassandra.io.compress.CompressedRandomAccessReader.reBuffer(CompressedRandomAccessReader.java:91)
at
org.apache.cassandra.io.util.RandomAccessReader.seek(RandomAccessReader.java:283)
at
org.apache.cassandra.io.util.PoolingSegmentedFile.getSegment(PoolingSegmentedFile.java:41)
at
org.apache.cassandra.io.sstable.SSTableReader.getFileDataInput(SSTableReader.java:1284)
at
org.apache.cassandra.db.columniterator.SimpleSliceReader.<init>(SimpleSliceReader.java:57)
at
org.apache.cassandra.db.columniterator.SSTableSliceIterator.createReader(SSTableSliceIterator.java:65)
at
org.apache.cassandra.db.columniterator.SSTableSliceIterator.<init>(SSTableSliceIterator.java:42)
at
org.apache.cassandra.db.filter.SliceQueryFilter.getSSTableColumnIterator(SliceQueryFilter.java:238)
at
org.apache.cassandra.db.filter.QueryFilter.getSSTableColumnIterator(QueryFilter.java:62)
at
org.apache.cassandra.db.CollationController.collectAllData(CollationController.java:250)
at
org.apache.cassandra.db.CollationController.getTopLevelColumns(CollationController.java:53)
at
org.apache.cassandra.db.ColumnFamilyStore.getTopLevelColumns(ColumnFamilyStore.java:1619)
at
org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore.java:1438)
at
org.apache.cassandra.db.Keyspace.getRow(Keyspace.java:340)
at
org.apache.cassandra.db.SliceFromReadCommand.getRow(SliceFromReadCommand.java:89)
at
org.apache.cassandra.cql3.statements.SelectStatement.readLocally(SelectStatement.java:318)
at
org.apache.cassandra.cql3.statements.SelectStatement.executeInternal(SelectStatement.java:338)
at
org.apache.cassandra.cql3.statements.SelectStatement.executeInternal(SelectStatement.java:67)
at
org.apache.cassandra.cql3.QueryProcessor.processInternal(QueryProcessor.java:208)
at
org.apache.cassandra.db.SystemKeyspace.checkHealth(SystemKeyspace.java:559)
at
org.apache.cassandra.service.CassandraDaemon.setup(CassandraDaemon.java:320)
at
org.apache.cassandra.service.CassandraDaemon.activate(CassandraDaemon.java:554)
at
org.apache.cassandra.service.CassandraDaemon.main(CassandraDaemon.java:643)
Caused by:
org.apache.cassandra.io.compress.CorruptBlockException:
(/var/lib/cassandra/data/system/local/system-local-jb-40-Data.db):
corruption detected, chunk at 0 of length 135.
at
org.apache.cassandra.io.compress.CompressedRandomAccessReader.decompressChunk(CompressedRandomAccessReader.java:122)
at
org.apache.cassandra.io.compress.CompressedRandomAccessReader.reBuffer(CompressedRandomAccessReader.java:87)
... 22 more
Caused by: java.io.IOException: Compressed lengths mismatch
at
org.apache.cassandra.io.compress.LZ4Compressor.uncompress(LZ4Compressor.java:98)
at
org.apache.cassandra.io.compress.CompressedRandomAccessReader.decompressChunk(CompressedRandomAccessReader.java:118)
... 23 more
Exception encountered during startup:
org.apache.cassandra.io.compress.CorruptBlockException:
(/var/lib/cassandra/data/system/local/system-local-jb-40-Data.db):
corruption detected, chunk at 0 of length 135.
$ tail -40 system.log
INFO [main] 2018-12-14 08:00:17,534 ColumnFamilyStore.java
(line 263) Initializing system.peers
INFO [main] 2018-12-14 08:00:17,543 ColumnFamilyStore.java
(line 263) Initializing system.local
INFO [SSTableBatchOpen:1] 2018-12-14 08:00:17,547
SSTableReader.java (line 239) Opening
/var/lib/cassandra/data/system/local/system-local-jb-39 (5262
bytes)
INFO [SSTableBatchOpen:3] 2018-12-14 08:00:17,547
SSTableReader.java (line 239) Opening
/var/lib/cassandra/data/system/local/system-local-jb-40 (139
bytes)
INFO [SSTableBatchOpen:2] 2018-12-14 08:00:17,547
SSTableReader.java (line 239) Opening
/var/lib/cassandra/data/system/local/system-local-jb-37 (5752
bytes)
INFO [SSTableBatchOpen:4] 2018-12-14 08:00:17,547
SSTableReader.java (line 239) Opening
/var/lib/cassandra/data/system/local/system-local-jb-38 (116
bytes)
INFO [main] 2018-12-14 08:00:17,627 AutoSavingCache.java (line
114) reading saved cache
/var/lib/cassandra/saved_caches/system-local-KeyCache-b.db
ERROR [main] 2018-12-14 08:00:17,797 CassandraDaemon.java (line
571) Exception encountered during startup
org.apache.cassandra.io.sstable.CorruptSSTableException:
org.apache.cassandra.io.compress.CorruptBlockException:
(/var/lib/cassandra/data/system/local/system-local-jb-40-Data.db):
corruption detected, chunk at 0 of length 135.
at
org.apache.cassandra.io.compress.CompressedRandomAccessReader.reBuffer(CompressedRandomAccessReader.java:91)
at
org.apache.cassandra.io.util.RandomAccessReader.seek(RandomAccessReader.java:283)
at
org.apache.cassandra.io.util.PoolingSegmentedFile.getSegment(PoolingSegmentedFile.java:41)
at
org.apache.cassandra.io.sstable.SSTableReader.getFileDataInput(SSTableReader.java:1284)
at
org.apache.cassandra.db.columniterator.SimpleSliceReader.<init>(SimpleSliceReader.java:57)
at
org.apache.cassandra.db.columniterator.SSTableSliceIterator.createReader(SSTableSliceIterator.java:65)
at
org.apache.cassandra.db.columniterator.SSTableSliceIterator.<init>(SSTableSliceIterator.java:42)
at
org.apache.cassandra.db.filter.SliceQueryFilter.getSSTableColumnIterator(SliceQueryFilter.java:238)
at
org.apache.cassandra.db.filter.QueryFilter.getSSTableColumnIterator(QueryFilter.java:62)
at
org.apache.cassandra.db.CollationController.collectAllData(CollationController.java:250)
at
org.apache.cassandra.db.CollationController.getTopLevelColumns(CollationController.java:53)
at
org.apache.cassandra.db.ColumnFamilyStore.getTopLevelColumns(ColumnFamilyStore.java:1619)
at
org.apache.cassandra.db.ColumnFamilyStore.getColumnFamily(ColumnFamilyStore.java:1438)
at
org.apache.cassandra.db.Keyspace.getRow(Keyspace.java:340)
at
org.apache.cassandra.db.SliceFromReadCommand.getRow(SliceFromReadCommand.java:89)
at
org.apache.cassandra.cql3.statements.SelectStatement.readLocally(SelectStatement.java:318)
at
org.apache.cassandra.cql3.statements.SelectStatement.executeInternal(SelectStatement.java:338)
at
org.apache.cassandra.cql3.statements.SelectStatement.executeInternal(SelectStatement.java:67)
at
org.apache.cassandra.cql3.QueryProcessor.processInternal(QueryProcessor.java:208)
at
org.apache.cassandra.db.SystemKeyspace.checkHealth(SystemKeyspace.java:559)
at
org.apache.cassandra.service.CassandraDaemon.setup(CassandraDaemon.java:320)
at
org.apache.cassandra.service.CassandraDaemon.activate(CassandraDaemon.java:554)
at
org.apache.cassandra.service.CassandraDaemon.main(CassandraDaemon.java:643)
Caused by:
org.apache.cassandra.io.compress.CorruptBlockException:
(/var/lib/cassandra/data/system/local/system-local-jb-40-Data.db):
corruption detected, chunk at 0 of length 135.
at
org.apache.cassandra.io.compress.CompressedRandomAccessReader.decompressChunk(CompressedRandomAccessReader.java:122)
at
org.apache.cassandra.io.compress.CompressedRandomAccessReader.reBuffer(CompressedRandomAccessReader.java:87)
... 22 more
Caused by: java.io.IOException: Compressed lengths mismatch
at
org.apache.cassandra.io.compress.LZ4Compressor.uncompress(LZ4Compressor.java:98)
at
org.apache.cassandra.io.compress.CompressedRandomAccessReader.decompressChunk(CompressedRandomAccessReader.java:118)
... 23 more
Now the problem is clear: cassandra database is corrupt, and it
fails to start. How to fix this, short of reinstalling the whole
node, is an issue which can be dealt with separately.
The point I'd like to make is that I think it was more difficult
than necessary to arrive at this point, and the experience could
be improved.
Firstly, if there are key underlying services like cassandra,
please could they be displayed on the front page? If there was a
red flag saying "Cassandra: stopped" I would have gone straight to
the cassandra logs.
Secondly, if the archiver is writing to esmond, and esmond finds
cassandra is down, surely esmond should return an error, and hence
the archiver should return an error? Even if the results are
buffered in postgres, an indication that problems copying from
postgres to the backend database would be very useful. I think
these sort of errors should appear in the pscheduler log, even
when debugging is turned off.
I think that the current logging, which says that archiver
writing to esmond was successful, is at best misleading.
(Architecturally, I'm not sure if the postgres buffering is done
in the archiver or in esmond. I thought the buffering was done by
pscheduler/archiver. But maybe the data *was* in fact written
successfully to esmond, but esmond is buffering in postgres,
waiting for cassandra to come back up)
Regards,
Brian Candler.
P.S. I do realise that this node has only 2GB which is below the
recommended minimum. However the number of tests configured is
very small, and there's enough swap space.
# free
total used free shared
buff/cache available
Mem: 1802244 1235196 153220
108684 413828 174904
Swap: 3932156 690852 3241304
==========
$ tail -50 pscheduler.log
Dec 14 08:31:22 perfsonar-border journal:
archiver-esmond/archive DEBUG Putting data to
https://41.79.97.10/esmond/perfsonar/archive/07dc383300c24247bbdea5145ab81adc/:
{'data': [{'ts': 1544776282, 'val': [{'val': 0.89, 'event-type':
'time-error-estimates'}, {'val': 0, 'event-type':
'packet-duplicates'}, {'val': {u'52.36': 1, u'52.71': 1,
u'52.75': 1, u'52.15': 4, u'52.79': 1, u'52.55': 1, u'52.32': 1,
u'52.19': 2, u'52.18': 5, u'52.39': 2, u'52.38': 2, u'52.13':
11, u'52.12': 5, u'52.37': 3, u'52.10': 19, u'52.16': 3,
u'52.33': 1, u'52.14': 7, u'51.98': 20, u'51.99': 26, u'51.93':
2, u'51.96': 9, u'51.97': 8, u'51.94': 1, u'51.95': 1, u'52.04':
55, u'52.05': 67, u'52.06': 40, u'52.07': 38, u'52.00': 29,
u'52.01': 32, u'52.02': 44, u'52.03': 61, u'52.40': 4, u'52.42':
1, u'52.43': 1, u'52.08': 31, u'52.09': 19, u'52.46': 1,
u'52.47': 1, u'52.48': 1, u'53.13': 1, u'52.28': 5, u'52.49': 1,
u'52.27': 3, u'52.24': 6, u'52.25': 2, u'52.22': 1, u'52.23': 1,
u'52.20': 3, u'52.21': 2, u'52.35': 1, u'52.81': 1, u'52.44': 1,
u'52.84': 1, u'52.66': 1, u'52.11': 8}, 'event-type':
'histogram-owdelay'}, {'val': {u'238': 600}, 'event-type':
'histogram-ttl'}, {'val': 600, 'event-type':
'packet-count-sent'}, {'val': 0, 'event-type':
'packet-reorders'}, {'val': 0, 'event-type':
'packet-count-lost'}, {'val': {'denominator': 600, 'numerator':
0}, 'event-type': 'packet-loss-rate'}, {'val': {'href':
'https://localhost/pscheduler/tasks/4417a262-528f-4d66-9134-4686a2798a16/runs/42b9508a-a30d-4782-9d02-e9fda63c8d03'},
'event-type': 'pscheduler-run-href'}]}]}
Dec 14 08:31:22 perfsonar-border journal: archiver
DEBUG 277725: Returned JSON from archiver: {u'succeeded':
True}
Dec 14 08:31:22 perfsonar-border journal: archiver
DEBUG 277725: Succeeded: 42b9508a-a30d-4782-9d02-e9fda63c8d03
to esmond
Dec 14 08:31:22 perfsonar-border journal: archiver
DEBUG 277725: Thread finished
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
276647: Got result: {"max-clock-error": 0.74,
"packets-duplicated": 0, "succeeded": true, "histogram-latency":
{"-0.02": 1, "-0.92": 3, "-0.77": 17, "-0.76": 18, "-0.75": 15,
"-0.74": 10, "-0.73": 8, "-0.72": 11, "-0.71": 5, "-0.70": 3,
"-0.91": 5, "-0.90": 7, "-0.79": 30, "-0.78": 25, "-0.58": 1,
"-0.66": 1, "-0.89": 4, "-0.86": 54, "-0.69": 4, "0.53": 1,
"-0.60": 1, "-0.63": 1, "-0.64": 1, "-0.65": 1, "-0.88": 19,
"-0.67": 3, "-0.68": 5, "-0.87": 42, "-0.84": 57, "-0.85": 66,
"-0.82": 40, "-0.83": 58, "-0.80": 44, "-0.81": 39},
"histogram-ttl": {"251": 600}, "packets-sent": 600,
"packets-reordered": 0, "packets-lost": 0, "packets-received":
600, "schema": 1}
Dec 14 08:31:23 perfsonar-border journal: runner INFO
276647: Posted result to
https://41.79.97.10/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba/runs/082a8a17-4a75-4d99-a2f0-b413e562e4fb
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
Schedule change.
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG Notifications: archiving_change
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG Refreshing default archivers from
/etc/pscheduler/default-archives
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG Nothing has changed; not updating.
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG Got 1 rows
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG 277726: Starting worker
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG Waiting 15.0 for change or notification
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG 277726: Thread running
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG 277726: Task is
https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG 277726: Run is
https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba/runs/082a8a17-4a75-4d99-a2f0-b413e562e4fb
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG 277726: Archiving to esmond: {'last-attempt': None,
'attempts': 0, 'result': {'reference': {u'created-by':
{u'user-agent': u'perfsonar-meshconfig', u'uuid':
u'AFFA819A-502D-11E7-BD32-D0BCC4BCA9AE', u'address':
u'41.79.97.10'}, u'description': u'Latency'}, 'schedule':
{'duration': 'P1D', 'start': '2018-12-14T08:31:23Z'}, 'tool':
{'version': u'1.0', 'name': u'powstream'}, 'participants':
[u'41.79.97.10'], 'result': {u'max-clock-error': 0.74,
u'packets-duplicated': 0, u'succeeded': True,
u'histogram-latency': {u'-0.02': 1, u'-0.92': 3, u'-0.77': 17,
u'-0.76': 18, u'-0.75': 15, u'-0.74': 10, u'-0.73': 8, u'-0.72':
11, u'-0.71': 5, u'-0.70': 3, u'-0.91': 5, u'-0.90': 7,
u'-0.79': 30, u'-0.78': 25, u'-0.58': 1, u'-0.88': 19, u'-0.89':
4, u'-0.86': 54, u'-0.87': 42, u'0.53': 1, u'-0.60': 1,
u'-0.63': 1, u'-0.64': 1, u'-0.65': 1, u'-0.66': 1, u'-0.67': 3,
u'-0.68': 5, u'-0.69': 4, u'-0.84': 57, u'-0.85': 66, u'-0.82':
40, u'-0.83': 58, u'-0.80': 44, u'-0.81': 39}, u'histogram-ttl':
{u'251': 600}, u'packets-sent': 600, u'packets-reordered': 0,
u'packets-lost': 0, u'packets-received': 600, u'schema': 1},
'test': {u'type': u'latencybg', u'spec': {u'source':
u'41.79.97.10', u'dest': u'169.239.249.2', u'packet-padding': 0,
u'data-ports': {u'upper': 9960, u'lower': 8760}, u'ip-version':
4, u'packet-interval': 0.1, u'duration': u'PT86400S',
u'packet-count': 600, u'schema': 1}}, 'id':
'082a8a17-4a75-4d99-a2f0-b413e562e4fb'}, 'task-href':
'https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba',
'run-href':
'https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba/runs/082a8a17-4a75-4d99-a2f0-b413e562e4fb',
'data': {u'url': u'https://localhost/esmond/perfsonar/archive/',
u'retry-policy': [{u'attempts': 1, u'wait': u'PT60S'}],
u'_auth-token': u'15a85870824ff1eb04b3729ff8bfa7ba9a6cc93d',
u'measurement-agent': u'41.79.97.10'}}
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG Pool esmond: Got a process
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG Archiver received:
{u'last-attempt': None, u'attempts': 0, u'result':
{u'reference': {u'created-by': {u'user-agent':
u'perfsonar-meshconfig', u'uuid':
u'AFFA819A-502D-11E7-BD32-D0BCC4BCA9AE', u'address':
u'41.79.97.10'}, u'description': u'Latency'}, u'schedule':
{u'duration': u'P1D', u'start': u'2018-12-14T08:31:23Z'},
u'tool': {u'version': u'1.0', u'name': u'powstream'},
u'participants': [u'41.79.97.10'], u'result':
{u'max-clock-error': 0.74, u'packets-duplicated': 0,
u'succeeded': True, u'histogram-latency': {u'-0.02': 1,
u'-0.92': 3, u'-0.77': 17, u'-0.76': 18, u'-0.75': 15, u'-0.74':
10, u'-0.73': 8, u'-0.72': 11, u'-0.71': 5, u'-0.70': 3,
u'-0.91': 5, u'-0.90': 7, u'-0.79': 30, u'-0.78': 25, u'-0.58':
1, u'-0.88': 19, u'-0.89': 4, u'-0.86': 54, u'-0.87': 42,
u'0.53': 1, u'-0.60': 1, u'-0.63': 1, u'-0.64': 1, u'-0.65': 1,
u'-0.66': 1, u'-0.67': 3, u'-0.68': 5, u'-0.69': 4, u'-0.84':
57, u'-0.85': 66, u'-0.82': 40, u'-0.83': 58, u'-0.80': 44,
u'-0.81': 39}, u'histogram-ttl': {u'251': 600}, u'packets-sent':
600, u'packets-reordered': 0, u'packets-lost': 0,
u'packets-received': 600, u'schema': 1}, u'test': {u'type':
u'latencybg', u'spec': {u'source': u'41.79.97.10', u'dest':
u'169.239.249.2', u'packet-padding': 0, u'data-ports':
{u'upper': 9960, u'lower': 8760}, u'ip-version': 4,
u'packet-interval': 0.1, u'duration': u'PT86400S',
u'packet-count': 600, u'schema': 1}}, u'id':
u'082a8a17-4a75-4d99-a2f0-b413e562e4fb'}, u'task-href':
u'https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba',
u'run-href':
u'https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba/runs/082a8a17-4a75-4d99-a2f0-b413e562e4fb',
u'data': {u'url':
u'https://localhost/esmond/perfsonar/archive/', u'retry-policy':
[{u'attempts': 1, u'wait': u'PT60S'}], u'_auth-token':
u'15a85870824ff1eb04b3729ff8bfa7ba9a6cc93d',
u'measurement-agent': u'41.79.97.10'}}
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG Archiver received:
{u'last-attempt': None, u'attempts': 0, u'result':
{u'reference': {u'created-by': {u'user-agent':
u'perfsonar-meshconfig', u'uuid':
u'AFFA819A-502D-11E7-BD32-D0BCC4BCA9AE', u'address':
u'41.79.97.10'}, u'description': u'Latency'}, u'schedule':
{u'duration': u'P1D', u'start': u'2018-12-14T08:31:23Z'},
u'tool': {u'version': u'1.0', u'name': u'powstream'},
u'participants': [u'41.79.97.10'], u'result':
{u'max-clock-error': 0.74, u'packets-duplicated': 0,
u'succeeded': True, u'histogram-latency': {u'-0.02': 1,
u'-0.92': 3, u'-0.77': 17, u'-0.76': 18, u'-0.75': 15, u'-0.74':
10, u'-0.73': 8, u'-0.72': 11, u'-0.71': 5, u'-0.70': 3,
u'-0.91': 5, u'-0.90': 7, u'-0.79': 30, u'-0.78': 25, u'-0.58':
1, u'-0.88': 19, u'-0.89': 4, u'-0.86': 54, u'-0.87': 42,
u'0.53': 1, u'-0.60': 1, u'-0.63': 1, u'-0.64': 1, u'-0.65': 1,
u'-0.66': 1, u'-0.67': 3, u'-0.68': 5, u'-0.69': 4, u'-0.84':
57, u'-0.85': 66, u'-0.82': 40, u'-0.83': 58, u'-0.80': 44,
u'-0.81': 39}, u'histogram-ttl': {u'251': 600}, u'packets-sent':
600, u'packets-reordered': 0, u'packets-lost': 0,
u'packets-received': 600, u'schema': 1}, u'test': {u'type':
u'latencybg', u'spec': {u'source': u'41.79.97.10', u'dest':
u'169.239.249.2', u'packet-padding': 0, u'data-ports':
{u'upper': 9960, u'lower': 8760}, u'ip-version': 4,
u'packet-interval': 0.1, u'duration': u'PT86400S',
u'packet-count': 600, u'schema': 1}}, u'id':
u'082a8a17-4a75-4d99-a2f0-b413e562e4fb'}, u'task-href':
u'https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba',
u'run-href':
u'https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba/runs/082a8a17-4a75-4d99-a2f0-b413e562e4fb',
u'data': {u'url':
u'https://localhost/esmond/perfsonar/archive/', u'retry-policy':
[{u'attempts': 1, u'wait': u'PT60S'}], u'_auth-token':
u'15a85870824ff1eb04b3729ff8bfa7ba9a6cc93d',
u'measurement-agent': u'41.79.97.10'}}
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG No metadata key found for
https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba@https://localhost/esmond/perfsonar/archive/
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG No metadata key found for
https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba@https://localhost/esmond/perfsonar/archive/
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG fast_mode is False
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG fast_mode is False
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG No metadata key, so posting to
esmond
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG No metadata key, so posting to
esmond
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG Posting metadata to
https://localhost/esmond/perfsonar/archive/: {'time-duration':
86400.0, 'sample-size': 600, 'pscheduler-test-type':
'latencybg', 'source': '41.79.97.10',
u'pscheduler-reference-created-by-user-agent':
u'perfsonar-meshconfig', 'measurement-agent': '41.79.97.10',
'input-destination': u'169.239.249.2', 'destination':
'169.239.249.2', u'pscheduler-reference-description':
u'Latency', 'event-types': [{'event-type': 'failures'},
{'summaries': [{'summary-type': 'aggregation', 'summary-window':
300, 'event-type': 'packet-count-sent'}, {'summary-type':
'aggregation', 'summary-window': 3600, 'event-type':
'packet-count-sent'}, {'summary-type': 'aggregation',
'summary-window': 86400, 'event-type': 'packet-count-sent'}],
'event-type': 'packet-count-sent'}, {'summaries':
[{'summary-type': 'aggregation', 'summary-window': 300,
'event-type': 'histogram-owdelay'}, {'summary-type':
'statistics', 'summary-window': 300, 'event-type':
'histogram-owdelay'}, {'summary-type': 'aggregation',
'summary-window': 3600, 'event-type': 'histogram-owdelay'},
{'summary-type': 'statistics', 'summary-window': 0,
'event-type': 'histogram-owdelay'}, {'summary-type':
'statistics', 'summary-window': 3600, 'event-type':
'histogram-owdelay'}, {'summary-type': 'aggregation',
'summary-window': 86400, 'event-type': 'histogram-owdelay'},
{'summary-type': 'statistics', 'summary-window': 86400,
'event-type': 'histogram-owdelay'}], 'event-type':
'histogram-owdelay'}, {'event-type': 'histogram-ttl'},
{'event-type': 'packet-duplicates'}, {'summaries':
[{'summary-type': 'aggregation', 'summary-window': 300,
'event-type': 'packet-loss-rate'}, {'summary-type':
'aggregation', 'summary-window': 3600, 'event-type':
'packet-loss-rate'}, {'summary-type': 'aggregation',
'summary-window': 86400, 'event-type': 'packet-loss-rate'}],
'event-type': 'packet-loss-rate'}, {'summaries':
[{'summary-type': 'aggregation', 'summary-window': 300,
'event-type': 'packet-count-lost'}, {'summary-type':
'aggregation', 'summary-window': 3600, 'event-type':
'packet-count-lost'}, {'summary-type': 'aggregation',
'summary-window': 86400, 'event-type': 'packet-count-lost'}],
'event-type': 'packet-count-lost'}, {'event-type':
'packet-reorders'}, {'event-type': 'time-error-estimates'},
{'event-type': 'pscheduler-run-href'}], 'subject-type':
'point-to-point', 'input-source': u'41.79.97.10',
'ip-packet-padding': 0, u'pscheduler-reference-created-by-uuid':
u'AFFA819A-502D-11E7-BD32-D0BCC4BCA9AE', 'tool-name':
u'pscheduler/powstream',
u'pscheduler-reference-created-by-address': u'41.79.97.10',
'time-probe-interval': 0.1}
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG Posting metadata to
https://localhost/esmond/perfsonar/archive/: {'time-duration':
86400.0, 'sample-size': 600, 'pscheduler-test-type':
'latencybg', 'source': '41.79.97.10',
u'pscheduler-reference-created-by-user-agent':
u'perfsonar-meshconfig', 'measurement-agent': '41.79.97.10',
'input-destination': u'169.239.249.2', 'destination':
'169.239.249.2', u'pscheduler-reference-description':
u'Latency', 'event-types': [{'event-type': 'failures'},
{'summaries': [{'summary-type': 'aggregation', 'summary-window':
300, 'event-type': 'packet-count-sent'}, {'summary-type':
'aggregation', 'summary-window': 3600, 'event-type':
'packet-count-sent'}, {'summary-type': 'aggregation',
'summary-window': 86400, 'event-type': 'packet-count-sent'}],
'event-type': 'packet-count-sent'}, {'summaries':
[{'summary-type': 'aggregation', 'summary-window': 300,
'event-type': 'histogram-owdelay'}, {'summary-type':
'statistics', 'summary-window': 300, 'event-type':
'histogram-owdelay'}, {'summary-type': 'aggregation',
'summary-window': 3600, 'event-type': 'histogram-owdelay'},
{'summary-type': 'statistics', 'summary-window': 0,
'event-type': 'histogram-owdelay'}, {'summary-type':
'statistics', 'summary-window': 3600, 'event-type':
'histogram-owdelay'}, {'summary-type': 'aggregation',
'summary-window': 86400, 'event-type': 'histogram-owdelay'},
{'summary-type': 'statistics', 'summary-window': 86400,
'event-type': 'histogram-owdelay'}], 'event-type':
'histogram-owdelay'}, {'event-type': 'histogram-ttl'},
{'event-type': 'packet-duplicates'}, {'summaries':
[{'summary-type': 'aggregation', 'summary-window': 300,
'event-type': 'packet-loss-rate'}, {'summary-type':
'aggregation', 'summary-window': 3600, 'event-type':
'packet-loss-rate'}, {'summary-type': 'aggregation',
'summary-window': 86400, 'event-type': 'packet-loss-rate'}],
'event-type': 'packet-loss-rate'}, {'summaries':
[{'summary-type': 'aggregation', 'summary-window': 300,
'event-type': 'packet-count-lost'}, {'summary-type':
'aggregation', 'summary-window': 3600, 'event-type':
'packet-count-lost'}, {'summary-type': 'aggregation',
'summary-window': 86400, 'event-type': 'packet-count-lost'}],
'event-type': 'packet-count-lost'}, {'event-type':
'packet-reorders'}, {'event-type': 'time-error-estimates'},
{'event-type': 'pscheduler-run-href'}], 'subject-type':
'point-to-point', 'input-source': u'41.79.97.10',
'ip-packet-padding': 0, u'pscheduler-reference-created-by-uuid':
u'AFFA819A-502D-11E7-BD32-D0BCC4BCA9AE', 'tool-name':
u'pscheduler/powstream',
u'pscheduler-reference-created-by-address': u'41.79.97.10',
'time-probe-interval': 0.1}
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
278273 is already running
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
276648 is already running
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
279264 is already running
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
277819 is already running
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
277817 is already running
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
276643 is already running
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
276644 is already running
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
277818 is already running
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
279266 is already running
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
276647 is already running
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
Skipped 10 already-running runs
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
No workers to run.
Dec 14 08:31:23 perfsonar-border journal: runner DEBUG
Next run or check in 0:01:00
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG Esmond returned HTTP 201:
{u'metadata-key': u'731acc8f36cf46ce8c30a26b55f8f0e9',
u'destination': u'169.239.249.2', u'pscheduler-test-type':
u'latencybg', u'time-duration': u'86400.0', u'url':
u'https://localhost/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/',
u'measurement-agent': u'41.79.97.10', u'input-destination':
u'169.239.249.2', u'sample-size': u'600', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/',
u'pscheduler-reference-description': u'Latency', u'event-types':
[{u'time-updated': None, u'summaries': [], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/time-error-estimates/base',
u'event-type': u'time-error-estimates'}, {u'time-updated': None,
u'summaries': [], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-duplicates/base',
u'event-type': u'packet-duplicates'}, {u'time-updated': None,
u'summaries': [], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/pscheduler-run-href/base',
u'event-type': u'pscheduler-run-href'}, {u'time-updated': None,
u'summaries': [], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-ttl/base',
u'event-type': u'histogram-ttl'}, {u'time-updated': None,
u'summaries': [{u'summary-type': u'aggregation',
u'summary-window': u'300', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-sent/aggregations/300',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'3600', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-sent/aggregations/3600',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'86400', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-sent/aggregations/86400',
u'time-updated': None}], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-sent/base',
u'event-type': u'packet-count-sent'}, {u'time-updated': None,
u'summaries': [], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-reorders/base',
u'event-type': u'packet-reorders'}, {u'time-updated': None,
u'summaries': [{u'summary-type': u'aggregation',
u'summary-window': u'300', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-lost/aggregations/300',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'3600', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-lost/aggregations/3600',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'86400', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-lost/aggregations/86400',
u'time-updated': None}], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-lost/base',
u'event-type': u'packet-count-lost'}, {u'time-updated': None,
u'summaries': [{u'summary-type': u'aggregation',
u'summary-window': u'300', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/aggregations/300',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'3600', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/aggregations/3600',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'86400', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/aggregations/86400',
u'time-updated': None}, {u'summary-type': u'statistics',
u'summary-window': u'0', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/statistics/0',
u'time-updated': None}, {u'summary-type': u'statistics',
u'summary-window': u'300', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/statistics/300',
u'time-updated': None}, {u'summary-type': u'statistics',
u'summary-window': u'3600', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/statistics/3600',
u'time-updated': None}, {u'summary-type': u'statistics',
u'summary-window': u'86400', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/statistics/86400',
u'time-updated': None}], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/base',
u'event-type': u'histogram-owdelay'}, {u'time-updated': None,
u'summaries': [], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/failures/base',
u'event-type': u'failures'}, {u'time-updated': None,
u'summaries': [{u'summary-type': u'aggregation',
u'summary-window': u'300', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-loss-rate/aggregations/300',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'3600', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-loss-rate/aggregations/3600',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'86400', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-loss-rate/aggregations/86400',
u'time-updated': None}], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-loss-rate/base',
u'event-type': u'packet-loss-rate'}], u'subject-type':
u'point-to-point', u'source': u'41.79.97.10', u'input-source':
u'41.79.97.10', u'ip-packet-padding': u'0',
u'pscheduler-reference-created-by-uuid':
u'AFFA819A-502D-11E7-BD32-D0BCC4BCA9AE', u'tool-name':
u'pscheduler/powstream',
u'pscheduler-reference-created-by-user-agent':
u'perfsonar-meshconfig',
u'pscheduler-reference-created-by-address': u'41.79.97.10',
u'time-probe-interval': u'0.1'}
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG Esmond returned HTTP 201:
{u'metadata-key': u'731acc8f36cf46ce8c30a26b55f8f0e9',
u'destination': u'169.239.249.2', u'pscheduler-test-type':
u'latencybg', u'time-duration': u'86400.0', u'url':
u'https://localhost/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/',
u'measurement-agent': u'41.79.97.10', u'input-destination':
u'169.239.249.2', u'sample-size': u'600', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/',
u'pscheduler-reference-description': u'Latency', u'event-types':
[{u'time-updated': None, u'summaries': [], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/time-error-estimates/base',
u'event-type': u'time-error-estimates'}, {u'time-updated': None,
u'summaries': [], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-duplicates/base',
u'event-type': u'packet-duplicates'}, {u'time-updated': None,
u'summaries': [], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/pscheduler-run-href/base',
u'event-type': u'pscheduler-run-href'}, {u'time-updated': None,
u'summaries': [], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-ttl/base',
u'event-type': u'histogram-ttl'}, {u'time-updated': None,
u'summaries': [{u'summary-type': u'aggregation',
u'summary-window': u'300', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-sent/aggregations/300',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'3600', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-sent/aggregations/3600',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'86400', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-sent/aggregations/86400',
u'time-updated': None}], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-sent/base',
u'event-type': u'packet-count-sent'}, {u'time-updated': None,
u'summaries': [], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-reorders/base',
u'event-type': u'packet-reorders'}, {u'time-updated': None,
u'summaries': [{u'summary-type': u'aggregation',
u'summary-window': u'300', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-lost/aggregations/300',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'3600', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-lost/aggregations/3600',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'86400', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-lost/aggregations/86400',
u'time-updated': None}], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-count-lost/base',
u'event-type': u'packet-count-lost'}, {u'time-updated': None,
u'summaries': [{u'summary-type': u'aggregation',
u'summary-window': u'300', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/aggregations/300',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'3600', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/aggregations/3600',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'86400', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/aggregations/86400',
u'time-updated': None}, {u'summary-type': u'statistics',
u'summary-window': u'0', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/statistics/0',
u'time-updated': None}, {u'summary-type': u'statistics',
u'summary-window': u'300', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/statistics/300',
u'time-updated': None}, {u'summary-type': u'statistics',
u'summary-window': u'3600', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/statistics/3600',
u'time-updated': None}, {u'summary-type': u'statistics',
u'summary-window': u'86400', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/statistics/86400',
u'time-updated': None}], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/histogram-owdelay/base',
u'event-type': u'histogram-owdelay'}, {u'time-updated': None,
u'summaries': [], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/failures/base',
u'event-type': u'failures'}, {u'time-updated': None,
u'summaries': [{u'summary-type': u'aggregation',
u'summary-window': u'300', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-loss-rate/aggregations/300',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'3600', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-loss-rate/aggregations/3600',
u'time-updated': None}, {u'summary-type': u'aggregation',
u'summary-window': u'86400', u'uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-loss-rate/aggregations/86400',
u'time-updated': None}], u'base-uri':
u'/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/packet-loss-rate/base',
u'event-type': u'packet-loss-rate'}], u'subject-type':
u'point-to-point', u'source': u'41.79.97.10', u'input-source':
u'41.79.97.10', u'ip-packet-padding': u'0',
u'pscheduler-reference-created-by-uuid':
u'AFFA819A-502D-11E7-BD32-D0BCC4BCA9AE', u'tool-name':
u'pscheduler/powstream',
u'pscheduler-reference-created-by-user-agent':
u'perfsonar-meshconfig',
u'pscheduler-reference-created-by-address': u'41.79.97.10',
u'time-probe-interval': u'0.1'}
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG Added metadata key
731acc8f36cf46ce8c30a26b55f8f0e9 for task
https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba@https://localhost/esmond/perfsonar/archive/
to memcache
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG Added metadata key
731acc8f36cf46ce8c30a26b55f8f0e9 for task
https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba@https://localhost/esmond/perfsonar/archive/
to memcache
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG Putting data to
https://localhost/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/:
{'data': [{'ts': 1544776283, 'val': [{'val': 0.74, 'event-type':
'time-error-estimates'}, {'val': 0, 'event-type':
'packet-duplicates'}, {'val': {u'-0.02': 1, u'-0.92': 3,
u'-0.77': 17, u'-0.76': 18, u'-0.75': 15, u'-0.74': 10,
u'-0.73': 8, u'-0.72': 11, u'-0.71': 5, u'-0.70': 3, u'-0.91':
5, u'-0.90': 7, u'-0.79': 30, u'-0.78': 25, u'-0.58': 1,
u'-0.88': 19, u'-0.89': 4, u'-0.86': 54, u'-0.87': 42, u'0.53':
1, u'-0.60': 1, u'-0.63': 1, u'-0.64': 1, u'-0.65': 1, u'-0.66':
1, u'-0.67': 3, u'-0.68': 5, u'-0.69': 4, u'-0.84': 57,
u'-0.85': 66, u'-0.82': 40, u'-0.83': 58, u'-0.80': 44,
u'-0.81': 39}, 'event-type': 'histogram-owdelay'}, {'val':
{u'251': 600}, 'event-type': 'histogram-ttl'}, {'val': 600,
'event-type': 'packet-count-sent'}, {'val': 0, 'event-type':
'packet-reorders'}, {'val': 0, 'event-type':
'packet-count-lost'}, {'val': {'denominator': 600, 'numerator':
0}, 'event-type': 'packet-loss-rate'}, {'val': {'href':
'https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba/runs/082a8a17-4a75-4d99-a2f0-b413e562e4fb'},
'event-type': 'pscheduler-run-href'}]}]}
Dec 14 08:31:23 perfsonar-border journal:
archiver-esmond/archive DEBUG Putting data to
https://localhost/esmond/perfsonar/archive/731acc8f36cf46ce8c30a26b55f8f0e9/:
{'data': [{'ts': 1544776283, 'val': [{'val': 0.74, 'event-type':
'time-error-estimates'}, {'val': 0, 'event-type':
'packet-duplicates'}, {'val': {u'-0.02': 1, u'-0.92': 3,
u'-0.77': 17, u'-0.76': 18, u'-0.75': 15, u'-0.74': 10,
u'-0.73': 8, u'-0.72': 11, u'-0.71': 5, u'-0.70': 3, u'-0.91':
5, u'-0.90': 7, u'-0.79': 30, u'-0.78': 25, u'-0.58': 1,
u'-0.88': 19, u'-0.89': 4, u'-0.86': 54, u'-0.87': 42, u'0.53':
1, u'-0.60': 1, u'-0.63': 1, u'-0.64': 1, u'-0.65': 1, u'-0.66':
1, u'-0.67': 3, u'-0.68': 5, u'-0.69': 4, u'-0.84': 57,
u'-0.85': 66, u'-0.82': 40, u'-0.83': 58, u'-0.80': 44,
u'-0.81': 39}, 'event-type': 'histogram-owdelay'}, {'val':
{u'251': 600}, 'event-type': 'histogram-ttl'}, {'val': 600,
'event-type': 'packet-count-sent'}, {'val': 0, 'event-type':
'packet-reorders'}, {'val': 0, 'event-type':
'packet-count-lost'}, {'val': {'denominator': 600, 'numerator':
0}, 'event-type': 'packet-loss-rate'}, {'val': {'href':
'https://localhost/pscheduler/tasks/a7a854ba-594c-4356-aea4-8f9aabe8f6ba/runs/082a8a17-4a75-4d99-a2f0-b413e562e4fb'},
'event-type': 'pscheduler-run-href'}]}]}
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG 277726: Returned JSON from archiver: {u'succeeded':
True}
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG 277726: Succeeded: 082a8a17-4a75-4d99-a2f0-b413e562e4fb
to esmond
Dec 14 08:31:23 perfsonar-border journal: archiver
DEBUG 277726: Thread finished
