search

gilesknap / gphotos-sync

Google Photos and Albums backup with Google Photos Library API
Apache License 2.0
2.02k stars 165 forks source link

Crash without log when running backgroud. #15

Closed prigal closed 6 years ago

prigal commented 6 years ago

Last nitght is started sync again with

gphotos-sync --db-path=var/ /media/toshiba/ >> var/gphotos.log &

This morning, program is not running, log is stopped on :

gphotos.picasa: Added 8574 /media/toshiba/picasa/2016/07/20160716_135918 (3).mp4

And when starting again, it restart from beginning, look like database has not been updated ^^

(gphotos.sqlite-journal was still present)

Maybe, a forced "database save" every 1K photos is a good idea !

gilesknap commented 6 years ago

Yes I have considered occasional dB updates, I will add this.

I have never seen such a crash before.

Is this the second time you ran against the same dB? Did you abort the previous run?

Thanks.

On Tue, 28 Nov 2017, 06:52 Pierre, notifications@github.com wrote:

Last nitght is started sync again with

gphotos-sync --db-path=var/ /media/toshiba/ >> var/gphotos.log &

This morning, program is not running, log is stopped on :

gphotos.picasa: Added 8574 /media/toshiba/picasa/2016/07/20160716_135918 (3).mp4

And when starting again, it restart from beginning, look like database has not been updated ^^

(gphotos.sqlite-journal was still present)

Maybe, a forced "database save" every 1K photos is a good idea !

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/gilesknap/gphotos-sync/issues/15, or mute the thread https://github.com/notifications/unsubscribe-auth/AA64255W37EBJ7w0MSPuPYfnVclax8zoks5s662wgaJpZM4QsxQW .

prigal commented 6 years ago

Yes it's the second time it occurs. Without log. Each time it start again from last db update (all picasa sync). Actually I try to abort run when I think about it because it forces a db update.

gilesknap commented 6 years ago

Is it always failing at the same point? Is it possible that the dB got corrupted by an aborted run? I think the only way of stopping cleanly is with keyboard interrupt.

If you previously aborted then you can tell if it was clean since it writes out a stack trace to a hidden file on clean abort. I forget the name but it is reasonably obvious.

On Tue, 28 Nov 2017, 08:16 Pierre, notifications@github.com wrote:

Yes it's the second time it occurs. Without log. Each time it start again from last db update (all picasa sync). Actually I try to abort run when I think about it because it forces a db update.

— You are receiving this because you commented.

Reply to this email directly, view it on GitHub https://github.com/gilesknap/gphotos-sync/issues/15#issuecomment-347446309, or mute the thread https://github.com/notifications/unsubscribe-auth/AA642-lZ-P4-wURAHZ6qKM77qG-DisHSks5s68FbgaJpZM4QsxQW .

prigal commented 6 years ago

No it's not failing on the same problem.

In fact last time it has continue, and it has started downloading for the first time. (it start with picasa)

Command was launched without log redirect nor background mode, so I had to kill it to go to lunch and restart it with background.

That was 1 hour ago and it's still running but no output .

....
gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170824_131826-ANIMATION.gif ...
gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170824_105454-ANIMATION.gif ...
gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170824_102847.mp4 ...
gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170824_093413-COLLAGE.jpg ...
gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170823_163016-COLLAGE.jpg ...
gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170823_162945-COLLAGE.jpg ...
gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170822_141821.mp4 ...
gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170812_134932-ANIMATION.gif ...
gphotos.picasa: Downloading /media/toshiba/picasa/2017/07/20170729_103800-ANIMATION.gif ...

gphotos.picasa: Downloading /media/toshiba/picasa/2017/07/20170712_190921.mp4 ...
gphotos.picasa: Downloading /media/toshiba/picasa/2017/07/20170711_194259-ANIMATION.gif ...
^Cgphotos: User cancelled download
gphotos: Done.
gphotos.data: Saving Database ...
gphotos.data: Database Saved.

then : 

(gphotos-sync) pi@raspberrypi:~/pyenvs/gphotos-sync $ gphotos-sync --db-path=var/ /media/toshiba/ > var/gphotos.log &
[1] 7976
(gphotos-sync) pi@raspberrypi:~/pyenvs/gphotos-sync $ tail -f var/gphotos.log
gphotos.drive: Indexing Drive Folders ...
gphotos.drive: Resolving paths ...
gphotos.drive: Drive Folders scanned.
gphotos.drive: Indexing Drive Files ...
gphotos.data: Saving Database ...
gphotos.data: Database Saved.
gphotos.picasa: Indexing Albums ...
gphotos.picasa: Album count 23
gphotos.picasa: Album: Auto Backup, photos: 41434, updated: 2017-11-26 09:12:24, published: 2017-11-26 09:03:29

Stuck on this line for 1 hour.

CPU is at 100% on raspberry.

capture d ecran 2017-11-28 a 12 53 07

gilesknap commented 6 years ago

This makes me think that running in the background is causing the issue, does that agree with what you have seen so far?

I'll try doing some background runs myself and see if I can reproduce the problem.

If it is still stuck you could try bringing to the foreground and aborting it.

Send me the file if you have it (I will change the stack trace output to not require the etc folder) If there is no file it might be in etc next to where gphotos is installed (in your virtual env ?)

On Tue, Nov 28, 2017 at 11:53 AM Pierre notifications@github.com wrote:

No it's not failing on the same problem.

In fact last time it has continue, and it has started downloading for the first time. (it start with picasa)

Command was launched without log redirect nor background mode, so I had to kill it to go to lunch and restart it with background.

That was 1 hour ago and it's still running but no output .

.... gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170824_131826-ANIMATION.gif ... gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170824_105454-ANIMATION.gif ... gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170824_102847.mp4 ... gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170824_093413-COLLAGE.jpg ... gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170823_163016-COLLAGE.jpg ... gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170823_162945-COLLAGE.jpg ... gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170822_141821.mp4 ... gphotos.picasa: Downloading /media/toshiba/picasa/2017/08/20170812_134932-ANIMATION.gif ... gphotos.picasa: Downloading /media/toshiba/picasa/2017/07/20170729_103800-ANIMATION.gif ...

gphotos.picasa: Downloading /media/toshiba/picasa/2017/07/20170712_190921.mp4 ... gphotos.picasa: Downloading /media/toshiba/picasa/2017/07/20170711_194259-ANIMATION.gif ... ^Cgphotos: User cancelled download gphotos: Done. gphotos.data: Saving Database ... gphotos.data: Database Saved.

then :

(gphotos-sync) pi@raspberrypi:~/pyenvs/gphotos-sync $ gphotos-sync --db-path=var/ /media/toshiba/ > var/gphotos.log & [1] 7976 (gphotos-sync) pi@raspberrypi:~/pyenvs/gphotos-sync $ tail -f var/gphotos.log gphotos.drive: Indexing Drive Folders ... gphotos.drive: Resolving paths ... gphotos.drive: Drive Folders scanned. gphotos.drive: Indexing Drive Files ... gphotos.data: Saving Database ... gphotos.data: Database Saved. gphotos.picasa: Indexing Albums ... gphotos.picasa: Album count 23 gphotos.picasa: Album: Auto Backup, photos: 41434, updated: 2017-11-26 09:12:24, published: 2017-11-26 09:03:29

Stuck on this line for 1 hour.

CPU is at 100% on raspberry.

[image: capture d ecran 2017-11-28 a 12 53 07] https://user-images.githubusercontent.com/895267/33318506-200a24c2-d43b-11e7-9219-cd8741f81969.png

— You are receiving this because you commented.

Reply to this email directly, view it on GitHub https://github.com/gilesknap/gphotos-sync/issues/15#issuecomment-347500603, or mute the thread https://github.com/notifications/unsubscribe-auth/AA642ypKxi6DeqWzIjwChNEafjUaFNSmks5s6_RTgaJpZM4QsxQW .

prigal commented 6 years ago

I will try what you ask later. Since last post, I went to lunch and back. There are 2 new lines in log file : 

gphotos.picasa: Updated /media/toshiba/picasa/2017/03/00013.MTS
gphotos.utils: token refresh: ya29.GlwSBdggnJIqQz-aZEJYxTVOIz8Vsv4uXtNsI0A5rvolRNlXyU0hurXpNggqcPm3BxR3pWfrhaYe798TW1ZhIZHvhqvUxEjlRS6SHAmSOGtewt9n5OHlcG88cs4UEg

I'm still waiting, cpu at 100%.

prigal commented 6 years ago

Just did it, nothing in etc/

I restart it in background to check.

prigal commented 6 years ago

Do it again, still nothing.

Restart in foreground mode, I will let it work an hour to check if it's moving forward.

gilesknap commented 6 years ago

OK I'll need to fix the stack trace dump, apologies.

It seems like it is still running, just very slow. Is memory OK? I'm not sure how to interpret htop output and the Mem bar looks full.

prigal commented 6 years ago

Memory was ok. Only 132M really used over 434.

Maybe you should add more logs in each steps, and a verbose mode to display them (that will help us trace where it hangs)

gilesknap commented 6 years ago

I just managed to get gphotos-sync to hang. I was testing background operation and accidentally ran two. One aborted with DB locked, I cancelled the other and then restarted. It then always locked up on indexing folders, very early.

I deleted the DB from the filesystem and all was well.

So it seems it is possible to corrupt the DB in a subtle way that causes a hang. It is possible that this is what you are seeing...

gilesknap commented 6 years ago

Further update. I have noticed that the picasa indexing phase is processor bound and hits 100% on one processor for most of its execution. This might be a bit rough on the Pi. The reason is that the Drive matching is running for each item discovered, each match may make several DB queries.

It would probably make sense to split the indexing of items in picasaWeb and the matching.

Matching would be processor intensive but should not take too long since it does not need to wait for responses from Google.

gilesknap commented 6 years ago

The evidence now suggests that this was due to a corrupt database. It seems that this may be caused by running two instances against the same DB (although db locking should handle this). I will add a singleton check to avoid this issue.

gilesknap commented 6 years ago

locking so that only one instance can run against a given db location has been added in cbe040db233b429cf818857693944498ba24d215