Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

tootctl media/account refresh Error processing 53521: Is a directory @ rb_sysopen #14817

Closed
DexterHaslem opened this issue Sep 19, 2020 · 19 comments · Fixed by #14867
Closed

Comments

@DexterHaslem
Copy link

this is on v3.2.0 release, i havent touched anything on my instance in a while but a strange problem started cropping up.
noticed 404ing media links which previously worked (local media server), so tried running:

mastodon@lpmasto:~/live$ ./bin/tootctl accounts refresh --domain=problem.domain
Error processing 53521: Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/accounts/avatars/000/053/521/original/
Error processing 53519: Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/accounts/avatars/000/053/519/original/
Error processing 53524: Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/accounts/avatars/000/053/524/original/
Error processing 53525: Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/accounts/avatars/000/053/525/original/
Error processing 53546: Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/accounts/avatars/000/053/546/original

... 
:mastodon@lpmasto:~/live$ ./bin/tootctl media refresh --domain=rip.domain
Error processing 748596: Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/media_attachments/files/000/748/596/original/
Error processing 748100: Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/media_attachments/files/000/748/100/original/
Error processing 748635: Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/media_attachments/files/000/748/635/original/
Error processing 748838: Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/media_attachments/files/000/748/838/original/
Error processing 748186: Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/media_attachments/files/000/748/186/original/

every single missing media (attachments, avatars, headers) prints this error. the directory exists and the file has a different file name than whats being served from the frontend. I've checked filehandle limits, and inode usage and they're all < 1% utilized. Any tips would be appreciated.

@ClearlyClaire
Copy link
Contributor

Could you run this again after editing lib/mastodon/cli_helper.rb to remove the two following lines:

            rescue => e
              progress.log pastel.red("Error processing #{item.id}: #{e}")

This should raise an error with more details so we can more easily figure out what is happening.

@DexterHaslem
Copy link
Author

Removing those two lines resulted in nothing be printed (aside from progress bar) completing normally. It seems to silently fail. I do not understand how it doesnt throw but am not very familiar with Ruby

@ClearlyClaire
Copy link
Contributor

hmpf… not what I expected… could you restore those lines and replace #{e} by #{e.backtrace}?

@DexterHaslem
Copy link
Author

Ok it printed pretty gnarly as one huge line per, so here is one with new lines added after the comma, so indentation is probably not right:

^[[31mError processing 53524: ["/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:42:in `initialize'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:42:in `open'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:42:in `rescue in block in flush_writes'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:39:in `block in flush_writes'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:37:in `each'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:37:in `flush_writes'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/attachment.rb:247:in `save'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/has_attached_file.rb:92:in `block in add_active_record_callbacks'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:426:in `instance_exec'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:426:in `block in make_lambda'",
 "/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:236:in `block in halting_and_conditional'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:517:in `block in invoke_after'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:517:in `each'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:517:in `invoke_after'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:133:in `run_callbacks'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/callbacks.rb:342:in `create_or_update'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/persistence.rb:275:in `save'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/validations.rb:46:in `save'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:310:in `block (2 levels) in save'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `block in transaction'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'", 
"/home/mastodon/.rbenv/versions/2.6.6/lib/ruby/2.6.0/monitor.rb:235:in `mon_synchronize'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'",
 "/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `transaction'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:212:in `transaction'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:310:in `block in save'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:325:in `rollback_active_record_state!'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:309:in `save'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/suppressor.rb:44:in `save'", 
"/home/mastodon/live/lib/mastodon/accounts_cli.rb:290:in `block in refresh'", 
"/home/mastodon/live/lib/mastodon/cli_helper.rb:52:in `block (4 levels) in parallelize_with_progress'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:416:in `with_connection'", 
"/home/mastodon/live/lib/mastodon/cli_helper.rb:51:in `block (3 levels) in parallelize_with_progress'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `block in synchronize'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:19:in `execute'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/ivar.rb:169:in `safe_execute'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/future.rb:55:in `block in execute'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:353:in `run_task'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:342:in `block (3 levels) in create_worker'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:325:in `loop'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:325:in `block (2 levels) in create_worker'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:324:in `catch'", 
"/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:324:in `block in create_worker'"]^[[0m
Progress: |

@DexterHaslem
Copy link
Author

DexterHaslem commented Sep 27, 2020

Some more background that might be useful: I did do tootctl upgrade storage-schema on the local media in past that appeared to work without problem. It was originally s3 backed then copied locally, again without issue though.

I just ran media remove-orphans for the first time in a while and it appears to be removing every single piece of media in accounts/avatars/, headers, etc as orphans 😮 I did backup before running it, so I am going to let it finish on the instance and see if it indeed nuked everything.

e: disregard above about the orphans, it was ripping through the remote media cache which was originally unclear, it appears to work normally. I will continue to investigate the original issue

@DexterHaslem
Copy link
Author

I was able to reproduce some kind of error trying accounts refresh on a single account:

mastodon@lpmasto:~/live$ ./bin/tootctl accounts refresh neikocat@blob.cat --verbose
Traceback (most recent call last):
        46: from ./bin/tootctl:8:in `<main>'
        45: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor/base.rb:466:in `start'
        44: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor.rb:387:in `dispatch'
        43: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor/invocation.rb:126:in `invoke_command'
        42: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor/command.rb:27:in `run'
        41: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor.rb:238:in `block in subcommand'
        40: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor/invocation.rb:115:in `invoke'
        39: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor.rb:387:in `dispatch'
        38: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor/invocation.rb:126:in `invoke_command'
        37: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor/command.rb:27:in `run'
        36: from /home/mastodon/live/lib/mastodon/accounts_cli.rb:306:in `refresh'
        35: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/suppressor.rb:44:in `save'
        34: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:309:in `save'
        33: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:325:in `rollback_active_record_state!'
        32: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:310:in `block in save'
        31: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
        30: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:212:in `transaction'
        29: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `transaction'
        28: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
        27: from /home/mastodon/.rbenv/versions/2.6.6/lib/ruby/2.6.0/monitor.rb:235:in `mon_synchronize'
        26: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
        25: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `block in transaction'
        24: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
        23: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:310:in `block (2 levels) in save'
        22: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/validations.rb:46:in `save'
        21: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/persistence.rb:275:in `save'
        20: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/callbacks.rb:342:in `create_or_update'
        19: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
        18: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:133:in `run_callbacks'
        17: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:517:in `invoke_after'                                                                                                       16: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:517:in `each'
        15: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:517:in `block in invoke_after'
        14: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:236:in `block in halting_and_conditional'
        13: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:426:in `block in make_lambda'
        12: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:426:in `instance_exec'
        11: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/has_attached_file.rb:92:in `block in add_active_record_callbacks'
        10: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/attachment.rb:247:in `save'
         9: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:37:in `flush_writes'
         8: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:37:in `each'
         7: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:40:in `block in flush_writes'
         6: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:95:in `move_file'
         5: from /home/mastodon/.rbenv/versions/2.6.6/lib/ruby/2.6.0/fileutils.rb:520:in `mv'
         4: from /home/mastodon/.rbenv/versions/2.6.6/lib/ruby/2.6.0/fileutils.rb:1555:in `fu_each_src_dest'
         3: from /home/mastodon/.rbenv/versions/2.6.6/lib/ruby/2.6.0/fileutils.rb:1573:in `fu_each_src_dest0'
         2: from /home/mastodon/.rbenv/versions/2.6.6/lib/ruby/2.6.0/fileutils.rb:1557:in `block in fu_each_src_dest'
         1: from /home/mastodon/.rbenv/versions/2.6.6/lib/ruby/2.6.0/fileutils.rb:529:in `block in mv'
/home/mastodon/.rbenv/versions/2.6.6/lib/ruby/2.6.0/fileutils.rb:529:in `rename': Not a directory @ rb_file_s_rename - (/tmp/438e969161990bd243ef0fc7ada963e620200927-31143-invvw, /home/mastodon/live/public/system/cache/accounts/headers/0
00/070/981/original/) (Errno::ENOTDIR)
        42: from ./bin/tootctl:8:in `<main>'
        41: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor/base.rb:466:in `start'
        40: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor.rb:387:in `dispatch'
        39: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor/invocation.rb:126:in `invoke_command'
        38: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor/command.rb:27:in `run'
        37: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor.rb:238:in `block in subcommand'
        36: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor/invocation.rb:115:in `invoke'
        35: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor.rb:387:in `dispatch'
        34: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor/invocation.rb:126:in `invoke_command'
        33: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/thor-0.20.3/lib/thor/command.rb:27:in `run'
        32: from /home/mastodon/live/lib/mastodon/accounts_cli.rb:306:in `refresh'
        31: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/suppressor.rb:44:in `save'
        30: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:309:in `save'
        29: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:325:in `rollback_active_record_state!'
        28: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:310:in `block in save'
        27: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
        26: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:212:in `transaction'
        25: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `transaction'
        24: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
        23: from /home/mastodon/.rbenv/versions/2.6.6/lib/ruby/2.6.0/monitor.rb:235:in `mon_synchronize'
        22: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
        21: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `block in transaction'
        20: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'                                                                        19: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:310:in `block (2 levels) in save'
        18: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/validations.rb:46:in `save'
        17: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/persistence.rb:275:in `save'
        16: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/callbacks.rb:342:in `create_or_update'
        15: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
        14: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:133:in `run_callbacks'
        13: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:517:in `invoke_after'
        12: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:517:in `each'
        11: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:517:in `block in invoke_after'
        10: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:236:in `block in halting_and_conditional'
         9: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:426:in `block in make_lambda'
         8: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:426:in `instance_exec'
         7: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/has_attached_file.rb:92:in `block in add_active_record_callbacks'
         6: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/attachment.rb:247:in `save'
         5: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:37:in `flush_writes'
         4: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:37:in `each'
         3: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:39:in `block in flush_writes'
         2: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:42:in `rescue in block in flush_writes'
         1: from /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:42:in `open'
/home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:42:in `initialize': Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/accounts/headers/000/070/981/original/ (Errno
::EISDIR)

I went and looked at that public/system/cache/accounts/headers/000/070/981 directory, it was empty.
I created an original dir (as user mastodon), and ran the command again and it didn't error. Afterwards, I tried to take a look again:

mastodon@lpmasto:~/live/public/system/cache/accounts/headers/000/070/981$ cd original/
-su: cd: original/: Permission denied

mastodon@lpmasto:~/live/public/system/cache/accounts/headers/000/070/981$ ls -al
total 20
drwxrwxr-x   3 mastodon mastodon  4096 Sep 27 05:21 .
drwxrwxr-x 505 mastodon mastodon 12288 Sep 23 02:30 ..
drw-rw-r--   2 mastodon mastodon  4096 Sep 27 05:21 original

... as root:

root@lpmasto:/home/mastodon/live/public/system/cache/accounts/headers/000/070/981/original# ls -al
total 252
drw-rw-r-- 2 mastodon mastodon   4096 Sep 27 05:21 .
drwxrwxr-x 3 mastodon mastodon   4096 Sep 27 05:21 ..
-rw------- 1 mastodon mastodon 248170 Sep 27 05:21 aff8b45c14daac25a2fbacf22dcbcf1f20200927-31228-tx8zqv
root@lpmasto:/home/mastodon/live/public/system/cache/accounts/headers/000/070/981/original# file aff8b45c14daac25a2fbacf22dcbcf1f20200927-31228-tx8zqv
aff8b45c14daac25a2fbacf22dcbcf1f20200927-31228-tx8zqv: PNG image data, 510 x 346, 8-bit/color RGBA, interlaced

so this is an example of an original dir becoming stuck I think. quite strange. something running during the command is stripping the execute bit on the directory.

to reiterate steps:

  1. media path ended up with no original dir
  2. created original dir, can enter it fine as mastodon (has execute bit)
  3. run tootctl accounts refresh for this account path (runs no errors)
  4. original dir no longer has execute bit
  5. running tootctl accounts refresh results in Permission denied @ rb_file_s_stat - /home/mastodon/live/public/system/cache/accounts/headers/000/070/981/original/98bb2199b941fe587d1657765086dfa520200927-31829-1kdrqyd (Errno::EACCES)
    bottom of error stack is /home/mastodon/live/vendor/bundle/ruby/2.6.0/gems/paperclip-6.0.0/lib/paperclip/storage/filesystem.rb:42:in initialize': Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/accounts/headers/000/070/981/original/ (Errno::EISDIR)
    `

while the fact the dir is missing in the first place is the first problem, hopefully this execute bit helps

@ClearlyClaire
Copy link
Contributor

Hmm this is weird indeed. It seems like Paperclip is for some reason treating the original directory as the media file itself?
I guess it could have to do with you copying from S3, although I'm very unsure of what exactly could cause this…

What happens if you type, in a Rails console (bundle exec rails c RAILS_ENV=production), the following?

Account.find_by(username: 'neikocat', domain: 'blob.cat').header_file_name
Account.find_by(username: 'neikocat', domain: 'blob.cat').header.path

@DexterHaslem
Copy link
Author

Moving from S3 worked fine for a few years. Forgot to mention, front end is trying to serve the dir as complete URL, eg domain.com/system/cache/accounts/headers/000/070/981/original , likely what you are wanting to see.

Something seems wrong w my rails console, i cant find that account or my own account but it seems to be loading production correctly:

mastodon@lpmasto:~/live$  export RAILS_ENV=production
mastodon@lpmasto:~/live$ bundle exec rails c
Chewy console strategy is `urgent`
Loading production environment (Rails 5.2.4.3)
irb(main):001:0> Account.find_by(username: 'neikocat', domain: 'blob.cat')
=> nil

@DexterHaslem
Copy link
Author

DexterHaslem commented Sep 27, 2020

here it is in db:


mastodon=# select header_file_name, header_content_type, header_file_size, header_updated_at from accounts where domain = 'blob.cat' and username = 'NeikoCat';
 header_file_name | header_content_type | header_file_size |     header_updated_at
------------------+---------------------+------------------+----------------------------
                  | image/png           |           248170 | 2020-09-27 09:37:58.880659
(1 row)

empty file name!

made me realize name is case sensitive, here's your original request:

irb(main):003:0> Account.find_by(username: 'NeikoCat', domain: 'blob.cat').header_file_name
=> ""
irb(main):004:0> Account.find_by(username: 'NeikoCat', domain: 'blob.cat').header.path
=> "/home/mastodon/live/public/system/cache/accounts/headers/000/070/981/original/"
irb(main):005:0> 

@ClearlyClaire
Copy link
Contributor

ok, the issue is definitely that the file name is empty. That should never happen and I have no idea how it happened.

I guess you could do something like

Account.where(header_file_name: '').in_batches.update_all(header_file_name: nil)
Account.where(avatar_file_name: '').in_batches.update_all(avatar_file_name: nil)
MediaAttachment.where(file_file_name: '').in_batches.update_all(file_file_name: nil)

Then things like tootctl account refresh and tootctl media refresh should work.

@DexterHaslem
Copy link
Author

Gave that a whirl, but the commands still blow up:

irb(main):016:0> MediaAttachment.where(file_file_name: '').count
=> 0
irb(main):017:0> Account.where(header_file_name: '').count
=> 0
irb(main):018:0> Account.where(avatar_file_name: '').count
=> 0
irb(main):019:0> MediaAttachment.where(file_file_name: '').count
=> 0
irb(main):020:0>
mastodon@lpmasto:~/live$ ./bin/tootctl accounts refresh --domain=blob.cat
Error processing 53521: Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/accounts/avatars/000/053/521/original/
Error processing 53519: Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/accounts/avatars/000/053/519/original/
Error processing 53524: Is a directory @ rb_sysopen - /home/mastodon/live/public/system/cache/accounts/avatars/000/053/524/original/

...

Refreshed 133 accounts

Tried a few problematic domains, no luck. I checked in console that the values are still nil

@ClearlyClaire
Copy link
Contributor

This is surprising. I suppose the following produces the same error?

Account.find_by(username: 'NeikoCat', domain: 'blob.cat').download_header!

What do the following commands result in?

a = Account.find_by(username: 'NeikoCat', domain: 'blob.cat')
a.header..original_filename
a.header_remote_url

Also, if the first thing errors out, could you edit lib/paperclip/response_with_limit_adapter.rb and change filename_from_content_disposition and filename_from_path so that they read like the following:

    def filename_from_content_disposition
      disposition = @target.response.headers['content-disposition']
      res = disposition&.match(/filename="([^"]*)"/)&.captures&.first
      Rails.logger.warn "DEBUG: from content-disposition: #{res.inspect}"
      Rails.logger.warn "DEBUG: content-disposition was: #{disposition}"
      res
    end

    def filename_from_path
      res = @target.response.uri.path.split('/').last
      Rails.logger.warn "DEBUG: from path: #{res.inspect}"
      Rails.logger.warn "DEBUG: path was: #{@target.response.uri.path}"
      res
    end

and run Account.find_by(username: 'NeikoCat', domain: 'blob.cat').download_header! in a rails console again?

@DexterHaslem
Copy link
Author

First download header:

Account.find_by(username: 'NeikoCat', domain: 'blob.cat').download_header!

[paperclip] Trying to link /tmp/d41d8cd98f00b204e9800998ecf8427e20200927-1425-svx5ps to /tmp/5ab42910354b8bf44e47f902673a5c1e20200927-1425-47n0pv
=> nil

properties:

a = Account.find_by(username: 'NeikoCat', domain: 'blob.cat')
irb(main):038:0> a.header_remote_url
=> "https://blob.cat/media/0fca5e99eaa69a72ed6ca096418b5c4ea65e9c974ea1a9f37b27ac59820503bd.png"
irb(main):039:0> a.header.original_filename
=> nil

after editing I ran again but no change:

irb(main):041:0> Account.find_by(username: 'NeikoCat', domain: 'blob.cat').download_header!
[paperclip] Trying to link /tmp/d41d8cd98f00b204e9800998ecf8427e20200927-1425-1f909o7 to /tmp/1d2abf5ff06938e3c5f574baecda8b5520200927-1425-o7oyd9
=> nil

frontend is proviting missing.png as header link, not sure when that changed.

I went to the headers dir and deleted the original dir with bad perms again to see what re-running download_header! did and the media dir is empty

@ClearlyClaire
Copy link
Contributor

Hm this sounds even weirder… could you retry with a Rails console launched this way? RAILS_LOG_LEVEL=debug bundle exec rails c

@DexterHaslem
Copy link
Author

Sure, haha.. what the:

irb(main):001:0> Account.find_by(username: 'NeikoCat', domain: 'blob.cat').download_header!
  Account Load (14.1ms)  SELECT  "accounts".* FROM "accounts" WHERE "accounts"."username" = $1 AND "accounts"."domain" = $2 LIMIT $3  [["username", "NeikoCat"], ["domain", "blob.cat"], ["LIMIT", 1]]
[httplog] GET https://blob.cat/media/0fca5e99eaa69a72ed6ca096418b5c4ea65e9c974ea1a9f37b27ac59820503bd.png completed with status code 302 in 0.63046 seconds
[httplog] GET https://blob.blob.cat/blobcatfiles/0fca5e99eaa69a72ed6ca096418b5c4ea65e9c974ea1a9f37b27ac59820503bd.png completed with status code 200 in 0.211471 seconds
DEBUG: from content-disposition: ""
DEBUG: content-disposition was: filename=""
[paperclip] Trying to link /tmp/d41d8cd98f00b204e9800998ecf8427e20200927-23356-acojo6 to /tmp/4414467588cfdcb5ed6b160cfb7dc6c020200927-23356-1hs8069
=> nil

@DexterHaslem
Copy link
Author

DexterHaslem commented Sep 27, 2020

It's funny because it is coming from the server like that

curl -v https://blob.blob.cat/blobcatfiles/0fca5e99eaa69a72ed6ca096418b5c4ea65e9c974ea1a9f37b27ac59820503bd.png

.. snip..


< HTTP/2 200
< server: nginx/1.14.0 (Ubuntu)
< date: Sun, 27 Sep 2020 19:06:20 GMT
< content-type: image/png
< content-length: 248170
< accept-ranges: bytes
< content-disposition: filename=""

@ClearlyClaire
Copy link
Contributor

Alright! Seems like a combination of a pleroma bug and a Mastodon bug to me. Investigating it.

@ClearlyClaire
Copy link
Contributor

Could you try the tootctl command again after cherry-picking #14867?

@DexterHaslem
Copy link
Author

Great, thanks! after cherry pick, account refresh worked

some more background info: while this particular instance is pleroma, its using external cdn, i believe MinIO. there was about 3k objects across a handful of other servers having same issue and at first glance it was all external cdns but I didnt have an easy way to see what kind

Gargron added a commit that referenced this issue Dec 18, 2020
* Fix 2FA/sign-in token sessions being valid after password change (#14802)

If someone tries logging in to an account and is prompted for a 2FA
code or sign-in token, even if the account's password or e-mail is
updated in the meantime, the session will show the prompt and allow
the login process to complete with a valid 2FA code or sign-in token

* Fix Move handler not being triggered when failing to fetch target (#15107)

When failing to fetch the target account, the ProcessingWorker fails
as expected, but since it hasn't cleared the `move_in_progress` flag,
the next attempt at processing skips the `Move` activity altogether.

This commit changes it to clear the flag when encountering any
unexpected error on fetching the target account. This is likely to
occur because, of, e.g., a timeout, when many instances query the
same actor at the same time.

* Fix slow distinct queries where grouped queries are faster (#15287)

About 2x speed-up on inboxes query

* Fix possible inconsistencies in tag search (#14906)

Do not downcase the queried tag before passing it to postgres when searching:
- tags are not downcased on creation
- `arel_table[:name].lower.matches(pattern)` generates an ILIKE anyway
- if Postgres and Rails happen to use different case-folding rules,
  downcasing before query but not before insertion may mean that some
  tags with some casings are not searchable

* Fix updating account counters when account_stat is not yet created (#15108)

* Fix account processing failing because of large collections (#15027)

Fixes #15025

* Fix downloading remote media files when server returns empty filename (#14867)

Fixes #14817

* Fix webfinger redirect handling in ResolveAccountService (#15187)

* Fix webfinger redirect handling in ResolveAccountService

ResolveAccountService#process_webfinger! handled a one-step webfinger
redirection, but only accepting the result if it matched the exact URI passed
as input, defeating the point of a redirection check.

Instead, use the same logic as in `ActivityPub::FetchRemoteAccountService`,
updating the resulting `acct:` URI with the result of the first webfinger
query.

* Add tests

* Remove dependency on unused and unmaintained http_parser.rb gem (#14574)

It seems that years ago, the “http” gem dependend on the “http_parser.rb” gem
(it now depends on the “http-parser” gem), and, still years ago, we pulled
it from git in order to benefit from a bugfix that wasn't released yet (#7467).

* Add tootctl maintenance fix-duplicates (#14860, #15201, #15264, #15349, #15359)

* Fix old migration script not being able to run if it fails midway (#15361)

* Fix old migration script not being able to run if it fails midway

Improve the robustness of a migration script likely to fail because of database
corruption so it can run again once database corruptions are fixed.

* Display a specific error message in case of index corruption

Co-authored-by: Eugen Rochko <eugen@zeonfederated.com>
Co-authored-by: Claire <claire.github-309c@sitedethib.com>

Co-authored-by: Eugen Rochko <eugen@zeonfederated.com>
Co-authored-by: Claire <claire.github-309c@sitedethib.com>
shouo1987 pushed a commit to CrossGate-Pawoo/mastodon that referenced this issue Dec 7, 2022
* Fix 2FA/sign-in token sessions being valid after password change (mastodon#14802)

If someone tries logging in to an account and is prompted for a 2FA
code or sign-in token, even if the account's password or e-mail is
updated in the meantime, the session will show the prompt and allow
the login process to complete with a valid 2FA code or sign-in token

* Fix Move handler not being triggered when failing to fetch target (mastodon#15107)

When failing to fetch the target account, the ProcessingWorker fails
as expected, but since it hasn't cleared the `move_in_progress` flag,
the next attempt at processing skips the `Move` activity altogether.

This commit changes it to clear the flag when encountering any
unexpected error on fetching the target account. This is likely to
occur because, of, e.g., a timeout, when many instances query the
same actor at the same time.

* Fix slow distinct queries where grouped queries are faster (mastodon#15287)

About 2x speed-up on inboxes query

* Fix possible inconsistencies in tag search (mastodon#14906)

Do not downcase the queried tag before passing it to postgres when searching:
- tags are not downcased on creation
- `arel_table[:name].lower.matches(pattern)` generates an ILIKE anyway
- if Postgres and Rails happen to use different case-folding rules,
  downcasing before query but not before insertion may mean that some
  tags with some casings are not searchable

* Fix updating account counters when account_stat is not yet created (mastodon#15108)

* Fix account processing failing because of large collections (mastodon#15027)

Fixes mastodon#15025

* Fix downloading remote media files when server returns empty filename (mastodon#14867)

Fixes mastodon#14817

* Fix webfinger redirect handling in ResolveAccountService (mastodon#15187)

* Fix webfinger redirect handling in ResolveAccountService

ResolveAccountService#process_webfinger! handled a one-step webfinger
redirection, but only accepting the result if it matched the exact URI passed
as input, defeating the point of a redirection check.

Instead, use the same logic as in `ActivityPub::FetchRemoteAccountService`,
updating the resulting `acct:` URI with the result of the first webfinger
query.

* Add tests

* Remove dependency on unused and unmaintained http_parser.rb gem (mastodon#14574)

It seems that years ago, the “http” gem dependend on the “http_parser.rb” gem
(it now depends on the “http-parser” gem), and, still years ago, we pulled
it from git in order to benefit from a bugfix that wasn't released yet (mastodon#7467).

* Add tootctl maintenance fix-duplicates (mastodon#14860, mastodon#15201, mastodon#15264, mastodon#15349, mastodon#15359)

* Fix old migration script not being able to run if it fails midway (mastodon#15361)

* Fix old migration script not being able to run if it fails midway

Improve the robustness of a migration script likely to fail because of database
corruption so it can run again once database corruptions are fixed.

* Display a specific error message in case of index corruption

Co-authored-by: Eugen Rochko <eugen@zeonfederated.com>
Co-authored-by: Claire <claire.github-309c@sitedethib.com>

Co-authored-by: Eugen Rochko <eugen@zeonfederated.com>
Co-authored-by: Claire <claire.github-309c@sitedethib.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants