On 08/02/18 15:26, Andy Seaborne wrote:
See https://issues.apache.org/jira/browse/JENA-1472
Excellent.  Thank you.

You already have independent verification so I won't rush to check it out myself.

I don't want to put a snapshot build in production so I'll wait for the next release.  If I notice the preamble to that, or I get a nudge, I'll check out its still fixed then (workload permitting).

Brian


On 30/01/18 09:38, Andy Seaborne wrote:
Recorded as
https://issues.apache.org/jira/browse/JENA-1472

Fuseki 2.4.1 was released with Jena 3.1.1 so it's RDF 1.1.

     Andy

On 30/01/18 09:00, Brian McBride wrote:
Hi Lorenz,


On 30/01/18 07:30, Lorenz Buehmann wrote:
Hi Brian,

I can't help you with this problem,
You have thanks.  You have reminded me I should check on the latest version of Fuseki (I hadn't realised the one I'm running is so old).

I've just tried it on 3.6.0 and get the same problematic behaviour.
but I'm wondering whether you have
to use this almost two years old version of Fuseki (2016-11-04) ?
Have to - no. though upgrading is a breaking change and needs a data rebuild.

There are tradeoffs to be made in updating to later versions. You sometimes get new bugs as well as fixes to old ones.  Some of our other services run Fuseki 1 for example, and they don't have this backup issue.

If fixing this issue turns out to require a code change, I will be updating.

Thanks again for your help.

Brian

Probably an update won't solve your issues, but it might fix other bugs.
Also, the performance might have been improved.


Cheers,

Lorenz


On 30.01.2018 08:05, Brian McBride wrote:
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





Reply via email to