My appologies if you have seen this before: I'm having a little trouble
unsubscribing from an obsolete email address.
I'm having a problem with fuseki backups. We do a nightly backup of a
Fuseki server and after about 3 weeks, the backups hang. Fuseki
continues serving queries normally. We are running Fuseki 2.4.1.
If anyone has any knowledge about what might be going wrong here, I'd
appreciate hearing about it, otherwise I'd be happy to (help)
investigate as best I can.
I have just caught the problem and poked around a little.
The fuseki log for the day begins:
[[
2018-01-26 01:52:25.482 INFO Admin :: [1650] POST
http://localhost:3030/$/backup/ds
2018-01-26 01:52:25.494 INFO Admin :: [1650] Backup
dataset /ds
]]
and contains nothing else (well it didn't when I first looked at it).
The log for the previous day begins:
[[
2018-01-25 01:52:46.083 INFO Admin :: [1551] POST
http://localhost:3030/$/backup/ds
2018-01-25 01:52:46.083 INFO Admin :: [1551] Backup
dataset /ds
2018-01-25 01:52:46.083 INFO Server :: Task : 21 : backup
2018-01-25 01:52:46.107 INFO Server :: [Task 21] starts :
backup
2018-01-25 01:52:46.107 INFO Backup :: [1551] >>>> Start
backup /ds -> /etc/fuseki/backups/ds_2018-01-25_01-52-46
2018-01-25 01:52:46.123 INFO Request :: 127.0.0.1 - -
[25/Jan/2018:01:52:46 +0000] "POST /$/backup/ds" 200 - "" "curl/7.47.0"
2018-01-25 01:52:46.123 INFO Admin :: [1551] 200 OK (39 ms)
2018-01-25 01:52:46.782 INFO Backup :: [1551] <<<< Finish
backup /ds -> /etc/fuseki/backups/ds_2018-01-25_01-52-46
2018-01-25 01:52:46.782 INFO Server :: [Task 21] finishes
: backup
]]
The command
wget http://localhost:3030/tasks
hangs.
The daily backups are requested by the command
[[
curl -X POST 'http://localhost:3030/$/backup/ds'
]]
This also hangs.
Restart fuseki and backups work again.
The problem is reproducable (in less than three weeks). I fired I
VirtualBox with the same configuration as our production servers and no
data. There is nothing I would consider unusual about the
configuration. The backup command is in the script
/usr/local/bin/fuseki-backup.
To reproduce use script test.sh:
[[
#!/bin/bash
for ((count=1; count<=25; count++))
do
echo starting backup $count
fuseki-backup
sleep 5
echo $count done
done
]]
which outputs:
[[
{
"taskId" : "1" ,
"requestId" : 1
}
1 done
starting backup 2
{
"taskId" : "2" ,
"requestId" : 2
}
2 done
starting backup 3
{
"taskId" : "3" ,
"requestId" : 3
}
3 done
...
18 done
starting backup 19
{
"taskId" : "19" ,
"requestId" : 19
}
19 done
starting backup 20
{
"taskId" : "20" ,
"requestId" : 20
}
20 done
starting backup 21
{
"taskId" : "21" ,
"requestId" : 21
}
21 done
starting backup 22
]]
and then hangs
The fuseki log contains:
[[
2018-01-26 08:10:45.773 INFO Server :: Fuseki 2.4.1
2018-01-26 08:10:45.921 INFO Config ::
FUSEKI_HOME=/usr/share/fuseki
2018-01-26 08:10:45.922 INFO Config ::
FUSEKI_BASE=/etc/fuseki
2018-01-26 08:10:45.926 INFO Servlet :: Initializing Shiro
environment
2018-01-26 08:10:45.926 INFO EnvironmentLoader :: Starting Shiro
environment initialization.
2018-01-26 08:10:45.931 INFO Config :: Shiro file:
file:///etc/fuseki/shiro.ini
2018-01-26 08:10:46.069 INFO EnvironmentLoader :: Shiro environment
initialized in 142 ms.
2018-01-26 08:10:46.070 INFO Config :: Configuration
file: /etc/fuseki/config.ttl
2018-01-26 08:10:46.572 WARN AssemblerHelp :: ja:loadClass:
Migration to Jena3: Converting com.hp.hpl.jena.tdb.TDB to
org.apache.jena.tdb.TDB
2018-01-26 08:10:47.448 INFO Config :: Register: /ds
2018-01-26 08:10:47.539 INFO Server :: Started 2018/01/26
08:10:47 UTC on port 3030
2018-01-26 08:19:03.997 INFO Admin :: [1] GET
http://localhost:3030/$/backup
2018-01-26 08:19:03.999 INFO Request :: 0:0:0:0:0:0:0:1 -
- [26/Jan/2018:08:19:03 +0000] "GET /$/backup" 200 - "" "Wget/1.17.1
(linux-gnu)"
2018-01-26 08:19:04.005 INFO Admin :: [1] 405 HTTP
method not allowed: GET (7 ms)
2018-01-26 08:22:42.728 INFO Admin :: [2] POST
http://localhost:3030/$/backup/ds
2018-01-26 08:22:42.729 INFO Admin :: [2] Backup dataset
/ds
2018-01-26 08:22:42.731 INFO Server :: Task : 1 : backup
2018-01-26 08:22:42.736 INFO Server :: [Task 1] starts :
backup
2018-01-26 08:22:42.738 INFO Backup :: [2] >>>> Start
backup /ds -> /etc/fuseki/backups/ds_2018-01-26_08-22-42
2018-01-26 08:22:42.740 INFO Request :: 0:0:0:0:0:0:0:1 -
- [26/Jan/2018:08:22:42 +0000] "POST /$/backup/ds" 200 - "" "curl/7.47.0"
2018-01-26 08:22:42.743 INFO Admin :: [2] 200 OK (11 ms)
2018-01-26 08:22:42.753 INFO Backup :: [2] <<<< Finish
backup /ds -> /etc/fuseki/backups/ds_2018-01-26_08-22-42
2018-01-26 08:22:42.753 INFO Server :: [Task 1] finishes
: backup
2018-01-26 08:22:52.767 INFO Admin :: [3] POST
http://localhost:3030/$/backup/ds
2018-01-26 08:22:52.767 INFO Admin :: [3] Backup dataset
/ds
2018-01-26 08:22:52.767 INFO Server :: Task : 2 : backup
2018-01-26 08:22:52.772 INFO Request :: 0:0:0:0:0:0:0:1 -
- [26/Jan/2018:08:22:52 +0000] "POST /$/backup/ds" 200 - "" "curl/7.47.0"
2018-01-26 08:22:52.772 INFO Admin :: [3] 200 OK (4 ms)
2018-01-26 08:22:52.777 INFO Server :: [Task 2] starts :
backup
2018-01-26 08:22:52.778 INFO Backup :: [3] >>>> Start
backup /ds -> /etc/fuseki/backups/ds_2018-01-26_08-22-52
2018-01-26 08:22:52.779 INFO Backup :: [3] <<<< Finish
backup /ds -> /etc/fuseki/backups/ds_2018-01-26_08-22-52
2018-01-26 08:22:52.780 INFO Server :: [Task 2] finishes
: backup
2018-01-26 08:23:02.796 INFO Admin :: [4] POST
http://localhost:3030/$/backup/ds
2018-01-26 08:23:02.796 INFO Admin :: [4] Backup dataset
/ds
2018-01-26 08:23:02.797 INFO Server :: Task : 3 : backup
2018-01-26 08:23:02.797 INFO Server :: [Task 3] starts :
backup
2018-01-26 08:23:02.797 INFO Backup :: [4] >>>> Start
backup /ds -> /etc/fuseki/backups/ds_2018-01-26_08-23-02
2018-01-26 08:23:02.798 INFO Backup :: [4] <<<< Finish
backup /ds -> /etc/fuseki/backups/ds_2018-01-26_08-23-02
2018-01-26 08:23:02.798 INFO Server :: [Task 3] finishes
: backup
...
2018-01-26 08:25:53.288 INFO Admin :: [21] POST
http://localhost:3030/$/backup/ds
2018-01-26 08:25:53.289 INFO Admin :: [21] Backup
dataset /ds
2018-01-26 08:25:53.289 INFO Server :: Task : 20 : backup
2018-01-26 08:25:53.289 INFO Server :: [Task 20] starts :
backup
2018-01-26 08:25:53.290 INFO Backup :: [21] >>>> Start
backup /ds -> /etc/fuseki/backups/ds_2018-01-26_08-25-53
2018-01-26 08:25:53.291 INFO Backup :: [21] <<<< Finish
backup /ds -> /etc/fuseki/backups/ds_2018-01-26_08-25-53
2018-01-26 08:25:53.291 INFO Server :: [Task 20] finishes
: backup
2018-01-26 08:25:53.292 INFO Request :: 0:0:0:0:0:0:0:1 -
- [26/Jan/2018:08:25:53 +0000] "POST /$/backup/ds" 200 - "" "curl/7.47.0"
2018-01-26 08:25:53.292 INFO Admin :: [21] 200 OK (3 ms)
2018-01-26 08:26:03.323 INFO Admin :: [22] POST
http://localhost:3030/$/backup/ds
2018-01-26 08:26:03.325 INFO Admin :: [22] Backup
dataset /ds
2018-01-26 08:26:03.325 INFO Server :: Task : 21 : backup
2018-01-26 08:26:03.326 INFO Server :: [Task 21] starts :
backup
2018-01-26 08:26:03.326 INFO Backup :: [22] >>>> Start
backup /ds -> /etc/fuseki/backups/ds_2018-01-26_08-26-03
2018-01-26 08:26:03.327 INFO Backup :: [22] <<<< Finish
backup /ds -> /etc/fuseki/backups/ds_2018-01-26_08-26-03
2018-01-26 08:26:03.327 INFO Server :: [Task 21] finishes
: backup
2018-01-26 08:26:03.330 INFO Request :: 0:0:0:0:0:0:0:1 -
- [26/Jan/2018:08:26:03 +0000] "POST /$/backup/ds" 200 - "" "curl/7.47.0"
2018-01-26 08:26:03.330 INFO Admin :: [22] 200 OK (5 ms)
2018-01-26 08:26:13.344 INFO Admin :: [23] POST
http://localhost:3030/$/backup/ds
2018-01-26 08:26:13.344 INFO Admin :: [23] Backup
dataset /ds
]]
and that is all.
It may be coincidence, but top tells me that Fuseki has 21 threads
running suggesting maybe there is a limit on the number of task threads
and backups are not freeing the thread at the end of the backup.
Brian
