On Jul 06 2015, Motomura Shinichi <[email protected]> wrote:
> On 2015/06/18 12:33, Nikolaus Rath wrote:
>> On Jun 15 2015, Motomura Shinichi <[email protected]> wrote:
>>> On 2015/06/14 13:30, Nikolaus Rath wrote:
>>>> On Jun 01 2015, Motomura Shinichi <[email protected]> wrote:
>>>>> I use s3ql-2.13 in CentOS7 packages with OpenStack Swift (/v1) as
>>>>> backed storage.
>>>>>
>>>>> S3ql is offen crached when the same file "s3ql_data_593221" tried to 
>>>>> delete.
>>>>>
>>>>> Is it a bug of s3ql?
>>>>
>>>> It sounds more like a problem with your swift cluster. Can you check if
>>>> S3QL previously created this object? My guess is that the object was
>>>> created on a different server and not propagated in-time to the server
>>>> that handled the delete request.
>>>
>>> Thank you for replying.
>>>
>>> The "s3ql_data_593221" is created by same server.
>>> The log is belowed.
>>>
>>> *) CREATE LOG on Swift
>>> Jun  1 01:33:05 swift5 object-server: 192.168.21.42 - -
>>> [31/May/2015:16:33:05 +0000] "PUT
>>> /sdb1/104326/AUTH_mail/tumail/s3ql_data_593221" 201 - "PUT
>>> https://swift-proxy.int.center.tottori-u.ac.jp/v1/AUTH_mail/tumail/s3ql_data_593221";
>>> "tx7932405594c94a639abb3-00556b37c1" "proxy-server 23208" 0.4451
>>>
>>> *) DELETE LOG on Swift
>>> Jun  1 02:00:21 swift5 object-server: 192.168.21.42 - -
>>> [31/May/2015:17:00:21 +0000] "DELETE
>>> /sdb1/104326/AUTH_mail/tumail/s3ql_data_593221" 204 - "DELETE
>>> https://swift-proxy.int.center.tottori-u.ac.jp/v1/AUTH_mail/tumail/s3ql_data_593221";
>>> "txdb28c26681314519ab627-00556b3e1a" "proxy-server 23208" 0.0066
>>>
>>> Jun  1 02:00:21 swift5 object-server: 192.168.21.42 - -
>>> [31/May/2015:17:00:21 +0000] "DELETE
>>> /sdb1/104326/AUTH_mail/tumail/s3ql_data_593221" 404 - "DELETE
>>> https://swift-proxy.int.center.tottori-u.ac.jp/v1/AUTH_mail/tumail/s3ql_data_593221";
>>> "tx64af8b5fb25f4bf1a9dec-00556b3e24" "proxy-server 23209" 0.0065
>>
>> Hmm. That's odd. Can you reproduce this? If so, could you run mount.s3ql
>> with --debug-module s3ql.block_cache,s3ql.backends.swift and upload
>> mount.log somewhere?
>
> I have the debug log.
> Can I send you ([email protected]) the upload site URL?

I've got the debug log. Here are the relevant parts:

2015-07-07 00:07:10.800 7980:CommitThread s3ql.block_cache.upload: created new 
object 632199
2015-07-07 00:07:10.802 7980:CommitThread s3ql.block_cache.put: got reader, 
enqueueing (<s3ql.block_cache.CacheEntry object at 0x7f79a078c670>, 632199)
2015-07-07 00:07:10.803 7980:Thread-4 s3ql.backends.swift.open_write: started 
with s3ql_data_632199
2015-07-07 00:07:10.988 7980:Thread-4 s3ql.backends.swift._do_request: started 
with 'PUT', '/s3ql_data_632199', None, None, 
CaseInsensitiveDict({'X-Object-meta-format': 'raw2', 'X-Object-meta-md5': 
'aM73luaKJEwLuew+XKxlJw==', 'X-Object-meta-002': "'encryption': 'None',", 
'X-Object-meta-000': "'format_version': 2,", 'X-Object-meta-001': 
"'compression': 'ZLIB',", 'Content-Type': 'application/octet-stream', 
'X-Object-meta-003': "'data': b'eyAgfQ==',"}), <_io.FileIO name=232 mode='rb+'>
2015-07-07 00:07:10.989 7980:Thread-4 s3ql.backends.swift._do_request_inner: 
started with PUT /v1/AUTH_mail/tumail/s3ql_data_632199
2015-07-07 00:07:10.990 7980:Thread-4 s3ql.backends.swift._do_request_inner: 
writing body data
2015-07-07 00:07:13.013 7980:Thread-4 s3ql.block_cache._do_upload: uploaded 
1540746 bytes in 2.210 seconds, 0.66 MiB/s

So at this point the object has been written.

2015-07-07 00:13:11.939 7980:CommitThread s3ql.block_cache._deref_block: 
removing object 632199
2015-07-07 00:13:11.941 7980:CommitThread s3ql.block_cache._deref_block: adding 
632199 to removal queue

now S3QL attempts to delete the object.

2015-07-07 00:13:11.965 7980:Thread-15 s3ql.block_cache._removal_loop: reading 
from queue (blocking=False)
2015-07-07 00:13:11.966 7980:Thread-15 s3ql.block_cache._removal_loop: 
removing: [632199]
2015-07-07 00:13:11.971 7980:Thread-15 s3ql.backends.swift.delete: started with 
s3ql_data_632199
2015-07-07 00:13:11.971 7980:Thread-15 s3ql.backends.swift._do_request: started 
with 'DELETE', '/s3ql_data_632199', None, None, None, None
2015-07-07 00:13:11.972 7980:Thread-15 s3ql.backends.swift._do_request_inner: 
started with DELETE /v1/AUTH_mail/tumail/s3ql_data_632199

This is the first delete request...

2015-07-07 00:13:11.989 7980:Thread-15 s3ql.backends.swift._do_request: 
OpenStack auth token seems to have expired, requesting new one.

...but it fails because the server reports that the Auth token has
expired. S3QL terminates the connection (because it has to connect to
the auth server first) and tries again:

2015-07-07 00:13:12.022 7980:Thread-15 s3ql.backends.swift.delete: started with 
s3ql_data_632199
2015-07-07 00:13:12.023 7980:Thread-15 s3ql.backends.swift._do_request: started 
with 'DELETE', '/s3ql_data_632199', None, None, None, None
2015-07-07 00:13:12.023 7980:Thread-15 s3ql.backends.swift._do_request: no 
active connection, calling _get_conn()

there's no active connection, so we try to get a new access token:

2015-07-07 00:13:12.023 7980:Thread-15 s3ql.backends.swift._get_conn: started
2015-07-07 00:13:12.024 7980:Thread-15 s3ql.backends.swift._get_conn: GET /v1.0
2015-07-07 00:13:12.043 7980:Thread-15 s3ql.backends.swift._get_conn: auth to 
/v1.0 failed, trying next path
2015-07-07 00:13:12.045 7980:Thread-15 s3ql.backends.swift._get_conn: GET 
/auth/v1.0

...now we have the access token...

2015-07-07 00:13:12.070 7980:Thread-15 s3ql.backends.swift._do_request_inner: 
started with DELETE /v1/AUTH_mail/tumail/s3ql_data_632199

.. and now we have sent the removal request. However, it seems that the
server told us again that this wasn't successful, because now S3QL
indeed tries to send the request again:

2015-07-07 00:13:22.141 7980:Thread-15 s3ql.backends.swift.delete: started with 
s3ql_data_632199
2015-07-07 00:13:22.143 7980:Thread-15 s3ql.backends.swift._do_request: started 
with 'DELETE', '/s3ql_data_632199', None, None, None, None
2015-07-07 00:13:22.143 7980:Thread-15
s3ql.backends.swift._do_request_inner: started with DELETE
/v1/AUTH_mail/tumail/s3ql_data_632199
2015-07-07 00:13:27.538 7980:Thread-15 root.excepthook: Uncaught top-level 
exception:
s3ql.backends.common.NoSuchObject: Backend does not have anything stored under 
key 's3ql_data_632199'

..unfortunately the exact server reply is not logged. Can you get the
reply from the server logs?

Otherwise I'm afraid you'll have to reproduce one more time, this time
including "s3ql.backends.common" in the "--debug-module" list (you can
remove s3ql.block_cache from the list at the same time, we don't need that).

Best,
-Nikolaus

-- 
GPG encrypted emails preferred. Key id: 0xD113FCAC3C4E599F
Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F

             »Time flies like an arrow, fruit flies like a Banana.«

-- 
You received this message because you are subscribed to the Google Groups 
"s3ql" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to [email protected].
For more options, visit https://groups.google.com/d/optout.

Reply via email to