#3688 Trac error: Dabatabase disk image is malformed
Closed: Fixed None Opened 11 years ago by pspacek.

= bug description =
Trac instance https://fedorahosted.org/freeipa/ fails with "Dabatabase disk image is malformed" error from time to time. Sometimes it loads properly and on the other attempt it fails.

Time of observation: 2013-03-04T09:16+0100


How to reproduce this issue:
Go to https://fedorahosted.org/freeipa/ticket/3478 as un-logged user.
Click to "Fedora Account Login".
Enter valid username and password.
The error should pop-up:
{{{
Trac detected an internal error:

DatabaseError: database disk image is malformed
}}}

This has been fixed now.

Thanks for reporting

We need to look into this better, as this occurs more often

When I now tried to add comment to https://fedorahosted.org/freeipa/ticket/3440, I hit the error again:

{{{
Trac detected an internal error:
DatabaseError: database disk image is malformed
}}}

I see the same problem now (2013-03-04T14:53+0100) when I try to log-in to FreeIPA trac:

==== How to reproduce ====

While doing a GET operation on /report/3, Trac issued an internal error.

I'm logged in as user pspacek.

Request parameters:
{{{
{'id': u'3'}
}}}

==== Python Traceback ====
{{{
Traceback (most recent call last):
File "/usr/lib/python2.6/site-packages/trac/web/main.py", line 525, in _dispatch_request
dispatcher.dispatch(req)
File "/usr/lib/python2.6/site-packages/trac/web/main.py", line 269, in dispatch
req.session.save()
File "/usr/lib/python2.6/site-packages/trac/web/session.py", line 117, in save
@self.env.with_transaction()
File "/usr/lib/python2.6/site-packages/trac/db/api.py", line 77, in transaction_wrapper
fn(ldb)
File "/usr/lib/python2.6/site-packages/trac/web/session.py", line 152, in save_session
""", (self.sid, authenticated))
File "/usr/lib/python2.6/site-packages/trac/db/util.py", line 65, in execute
return self.cursor.execute(sql_escape_percent(sql), args)
File "/usr/lib/python2.6/site-packages/trac/db/sqlite_backend.py", line 78, in execute
result = PyFormatCursor.execute(self, args)
File "/usr/lib/python2.6/site-packages/trac/db/sqlite_backend.py", line 56, in execute
args or [])
File "/usr/lib/python2.6/site-packages/trac/db/sqlite_backend.py", line 48, in _rollback_on_error
return function(self,
args, **kwargs)
DatabaseError: database disk image is malformed
}}}

This should be corrected now, but we are quite puzzled how the corruption is happening. ;(

Please do let us know when/if you see it again and we will continue to try and trac down root cause.

Hello,
the database corruption is back. I received an exception when I tried to update ticket https://fedorahosted.org/freeipa/ticket/3519

{{{
Warning:
The change has been saved, but an error occurred while sending notifications: database disk image is malformed
The change has been saved, but an error occurred while sending notifications: database disk image is malformed
}}}

This is the traceback it gave me:

{{{
File "/usr/lib/python2.6/site-packages/trac/web/main.py", line 525, in _dispatch_request
dispatcher.dispatch(req)
File "/usr/lib/python2.6/site-packages/trac/web/main.py", line 246, in dispatch
resp = chosen_handler.process_request(req)
File "/usr/lib/python2.6/site-packages/trac/ticket/web_ui.py", line 169, in process_request
return self._process_ticket_request(req)
File "/usr/lib/python2.6/site-packages/trac/ticket/web_ui.py", line 541, in _process_ticket_request
self._do_save(req, ticket, action)
File "/usr/lib/python2.6/site-packages/trac/ticket/web_ui.py", line 1262, in _do_save
req.redirect(req.href.ticket(ticket.id) + fragment)
File "/usr/lib/python2.6/site-packages/trac/web/api.py", line 362, in redirect
self.session.save() # has to be done before the redirect is sent
File "/usr/lib/python2.6/site-packages/trac/web/session.py", line 117, in save
@self.env.with_transaction()
File "/usr/lib/python2.6/site-packages/trac/db/api.py", line 77, in transaction_wrapper
fn(ldb)
File "/usr/lib/python2.6/site-packages/trac/web/session.py", line 152, in save_session
""", (self.sid, authenticated))
File "/usr/lib/python2.6/site-packages/trac/db/util.py", line 65, in execute
return self.cursor.execute(sql_escape_percent(sql), args)
File "/usr/lib/python2.6/site-packages/trac/db/sqlite_backend.py", line 78, in execute
result = PyFormatCursor.execute(self, args)
File "/usr/lib/python2.6/site-packages/trac/db/sqlite_backend.py", line 56, in execute
args or [])
File "/usr/lib/python2.6/site-packages/trac/db/sqlite_backend.py", line 48, in _rollback_on_error
return function(self,
args, **kwargs)
}}}

When I tried to do the update again, it suddenly worked. Maybe the database is corrupted only on one replicated host - IIRC, there 2 of them, serving FreeIPA Trac instance.

There are indeed two hosts serving fedorahosted.org.
I just checked the database file on both, and they both mark it as non-broken.
Maybe it was some sort of cache somewhere? Could you report if the error shows up again?

I do not know what is the root cause. But it is something that needs to be known of as current architecture is a bit fragile. I think you were also considering rolling a real database server instead of current SQLite file.

I cannot access https://fedorahosted.org/freeipa/ticket/3519 at all, database malfunction is here again:

{{{
Traceback (most recent call last):
File "/usr/lib/python2.6/site-packages/trac/web/api.py", line 446, in send_error
data, 'text/html')
File "/usr/lib/python2.6/site-packages/trac/web/chrome.py", line 833, in render_template
message = req.session.pop('chrome.%s.%d' % (type_, i))
File "/usr/lib/python2.6/site-packages/trac/web/api.py", line 216, in getattr
value = self.callbacksname
File "/usr/lib/python2.6/site-packages/trac/web/main.py", line 309, in _get_session
return Session(self.env, req)
File "/usr/lib/python2.6/site-packages/trac/web/session.py", line 224, in init
self.get_session(req.authname, authenticated=True)
File "/usr/lib/python2.6/site-packages/trac/web/session.py", line 240, in get_session
super(Session, self).get_session(sid, authenticated)
File "/usr/lib/python2.6/site-packages/trac/web/session.py", line 95, in get_session
""", (sid, int(authenticated)))
File "/usr/lib/python2.6/site-packages/trac/db/util.py", line 65, in execute
return self.cursor.execute(sql_escape_percent(sql), args)
File "/usr/lib/python2.6/site-packages/trac/db/sqlite_backend.py", line 79, in execute
self.rows = PyFormatCursor.fetchall(self)
DatabaseError: database disk image is malformed
}}}

When I try to access https://fedorahosted.org/freeipa/report/3 I get the very same exception making - this error makes our Trac instance unusable for me.

Both these load ok for me here...

Are you logged in?

Can you try a shift refresh?

Replying to [comment:13 kevin]:

Both these load ok for me here...

Are you logged in?

Can you try a shift refresh?

I investigated it and found out it is happening only in my browser. I removed trac_form_token and trac_session cookies and it started working again... very strange behavior.

... it works until I try to log in. Then I get the good old

{{{
Traceback (most recent call last):
File "/usr/lib/python2.6/site-packages/trac/web/api.py", line 446, in send_error
data, 'text/html')
File "/usr/lib/python2.6/site-packages/trac/web/chrome.py", line 833, in render_template
message = req.session.pop('chrome.%s.%d' % (type_, i))
File "/usr/lib/python2.6/site-packages/trac/web/api.py", line 216, in getattr
value = self.callbacksname
File "/usr/lib/python2.6/site-packages/trac/web/main.py", line 309, in _get_session
return Session(self.env, req)
File "/usr/lib/python2.6/site-packages/trac/web/session.py", line 224, in init
self.get_session(req.authname, authenticated=True)
File "/usr/lib/python2.6/site-packages/trac/web/session.py", line 240, in get_session
super(Session, self).get_session(sid, authenticated)
File "/usr/lib/python2.6/site-packages/trac/web/session.py", line 95, in get_session
""", (sid, int(authenticated)))
File "/usr/lib/python2.6/site-packages/trac/db/util.py", line 65, in execute
return self.cursor.execute(sql_escape_percent(sql), args)
File "/usr/lib/python2.6/site-packages/trac/db/sqlite_backend.py", line 79, in execute
self.rows = PyFormatCursor.fetchall(self)
DatabaseError: database disk image is malformed
}}}

Interesting thing is, that my colleague was able to log in successfully. Does this mean that only my account cause the database malfunction?

I am waiting for any advice/response, this issue is pretty much blocking my work on the project.

Can you try again now? we did a reload of the db...

Thanks for quick response, I am able to log in now.

great.

Things are not fully right with the cluster, but we are stable now I think, so we are likely going to leave it this way until we can figure out a better solution. ;(

Would your project be interested in helping us test a 'fedorahostedv2' type thing with a better setup?

Sorry for all this trouble...

I'm getting this error reliably now whenever I attempt to close a ticket in the SSSD Trac instance.

ok. Will investigate. The sqlite db itself has no problems/issues... so it must be something with the trac session data being wrong. ;(

Can you try now? I cleared up 3 warnings in the db...

Replying to [comment:23 kevin]:

Can you try now? I cleared up 3 warnings in the db...

The trac instance is very slow now, but works. Thank you!

Hi,

I just got hit by the bug again. I can't create a new ticket in the upstream trac. Is there any way I can provide more information?

I just rebuilt the freeipa database again. Please notify me if this didn't solve your issues

We hit the database malformed again when I tried to open https://fedorahosted.org/freeipa/ticket/3492 AND I am signed in:

{{{
Traceback (most recent call last):
File "/usr/lib/python2.6/site-packages/trac/web/api.py", line 446, in send_error
data, 'text/html')
File "/usr/lib/python2.6/site-packages/trac/web/chrome.py", line 833, in render_template
message = req.session.pop('chrome.%s.%d' % (type_, i))
File "/usr/lib/python2.6/site-packages/trac/web/api.py", line 216, in getattr
value = self.callbacksname
File "/usr/lib/python2.6/site-packages/trac/web/main.py", line 309, in _get_session
return Session(self.env, req)
File "/usr/lib/python2.6/site-packages/trac/web/session.py", line 224, in init
self.get_session(req.authname, authenticated=True)
File "/usr/lib/python2.6/site-packages/trac/web/session.py", line 240, in get_session
super(Session, self).get_session(sid, authenticated)
File "/usr/lib/python2.6/site-packages/trac/web/session.py", line 95, in get_session
""", (sid, int(authenticated)))
File "/usr/lib/python2.6/site-packages/trac/db/util.py", line 65, in execute
return self.cursor.execute(sql_escape_percent(sql), args)
File "/usr/lib/python2.6/site-packages/trac/db/sqlite_backend.py", line 78, in execute
result = PyFormatCursor.execute(self, args)
File "/usr/lib/python2.6/site-packages/trac/db/sqlite_backend.py", line 56, in execute
args or [])
File "/usr/lib/python2.6/site-packages/trac/db/sqlite_backend.py", line 48, in _rollback_on_error
return function(self,
args, **kwargs)
DatabaseError: database disk image is malformed
}}}

We are going to be moving your trac instance (and some others) to different storage.

There will be a very short (few minutes) outage when we do that soon... after that we hope that this problem will go away.

Sorry again for all the trouble...

ok, freeipa has been moved.

Can you test now?

Is the malformed thing gone?

Is access any faster?

Hello kevin, thanks for the effort.

I see no error currently, Trac is slightly faster - not fast, but faster than it was before :-) I am not sure if we can get much faster with SQLite database backend...

Anyway, this looks OK now, so I will close the ticket.

Login to comment on this ticket.

Metadata