Transaction attachments are written to NFS share with zero size

GregSutcliffe commented 10 months ago

Support guidelines

[X] I've read the support guidelines

I've found a bug and checked that ...

[X] ... the documentation does not mention anything about my problem
[X] ... there are no open or closed issues that are related to my problem
[X] ... it's definitely a Firefly III issue, not me

Description

Hi, and thanks for Firefly3, it's awesome :)

Having tested it locally using Docker and local storage (which works 100% fine), I migrated F3 to server. That uses an NFS share for storage, and since moving over, I've noticed that attachments I add to a transaction are written with zero size. They are created, so this isn't a permissions error (I had that issue too, before correctly setting owner with chown), and it's not a general write issue because I can create files on the NFS share from the commandline (eg echo SUCCESS > f3uploads/test.txt).

Intrigued, I went back and tried using an NFS share with my local container, and the same behaviour occurs. I don't see any issues logged to the container logs until I try to read the file (which obviously fails). I also don't see anything useful in dmesg and journalctl.

I figure I'm likely in a minority using NFS here, and I'm happy to poke about - is there any way to at least get more debug info out of the writing-to-disk part of the operation? Thanks!

Debug information

Debug information generated at 2023-10-30 09:45:28 for Firefly III version v6.0.27.

System information
Item	Value
Firefly III	v6.0.27 / v2.0.10 / 20 (exp. 20)
PHP version	8.2.11 / apache2handler / Linux
BCscale	12
Error reporting	Display: Off, reporting: ALL errors
Max upload	67108864 (64 MB)
Database drivers	mysql, *pgsql*, sqlite,
Docker build	#723, base #39

Firefly III information
Item	Value
Timezone	UTC + Europe/London
App environment	local, debug: false
Layout	v1
Logging	info, stack / (empty)
Cache driver	file
Default language and locale	en_US + equal
Trusted proxies
Login provider & user guard	eloquent / web
Login headers	N/A + N/A
Stateful domains
Last cron job	never (never)
Mailer	log

User-specific information
Item	Value
User	#1 of 1
User flags	:credit_card: :wrench: :email:
Session start	2023-09-30 00:00:00
Session end	2023-10-30 23:59:59
View range	last30
User language	en_GB
User locale	en_GB
Locale(s) supported	en_GB.utf8: :white_check_mark: en_GB.UTF-8: :white_check_mark:
User agent	Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/118.0

Expected behaviour

Adding an attachment should save correctly when using NFS for the upload directiory

Steps to reproduce

Mount an NFS share at ./f3uploads
Start the container with -v /f3uploads:/var/www/html/storage/upload
Create a transaction
Edit the transaction, add an attachement, save it

Run ls -lh ./f3uploads and observe:

-rw-r--r-- 1 100032 100032    0 Oct 30 09:41 at-6.data

(optional) Log into the container and check writing a file manually works
- docker exec -it firefly3-app bash
- echo SUCCESS > /var/www/html/storage/upload/test.txt
- exit
- cat ./f3uploads/test.txt SUCCESS

Additional info

The same behaviour happens if you add the attachment while creating the transaction, instead of adding it as a later Edit step.

Here's the webserver log for the upload above:

10.0.2.100 - - [30/Oct/2023:09:41:12 +0000] "PUT /api/v1/transactions/165?_token=(redacted) HTTP/1.1" 200 2729 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/118.0"
10.0.2.100 - - [30/Oct/2023:09:41:12 +0000] "POST /api/v1/attachments HTTP/1.1" 200 1536 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/118.0"
[Mon Oct 30 09:41:12.955298 2023] [php:warn] [pid 84] [client 10.0.2.100:37248] PHP Warning:  PHP Request Startup: Input variables exceeded 1000. To increase the limit change max_input_vars in php.ini. in Unknown on line 0
10.0.2.100 - - [30/Oct/2023:09:41:12 +0000] "POST /api/v1/attachments/6/upload HTTP/1.1" 204 890 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/118.0"

Looking at the logs for a successful non-NFS write, they are both coded 204, so I assume the software thinks it worked.

JC5 commented 10 months ago

It's probably something in the underlying filesystem adaptor, but I've never taken a closer look. I'll see what I can find.

github-actions[bot] commented 10 months ago

Hi there! This is an automatic reply. Share and enjoy

This issue has been marked as being in triage. The root cause is not known yet, or the issue needs more investigation. You can help by sharing debug information (from /debug) if you also have this issue or when you haven't already done so.

Thank you for your contributions.

GregSutcliffe commented 10 months ago

Thanks for the fast reply! Happy to poke about, set it up outside of Docker, etc, if you need me to.

JC5 commented 10 months ago

Feel free! I have no idea what to look for, and there's a good chance I can't fix it from my end anyway.

GregSutcliffe commented 10 months ago

Will do! Any debugging tips? I notice App environment | local, debug: false in the debug output above, presumably I should set that to true somehow?

GregSutcliffe commented 10 months ago

OK, so I can reproduce it on an Ubuntu VM with a LAMP 8.2 stack, so it's not some container weirdness. My steps:

Created a VM, installed PHP 8.2, installed PSQL, installed Firefly-iii. I set debug to true in .env
Logged in, created a transaction, added an attachment
- Verified the file was in /var/www/firefly-iii/storage/uploads with proper size
Mounted the NFS share at /var/www/firefly-iii/storage/uploads
sudo -u www-data -s /bin/bash to get a shell and verified the web user could write to the share
Edited the transaction and added another attachement
- This one had 0 size again

I can't anything in the logs for Apache2. The /debug page shows PHP going into the storage methods but no further info:

...
[2023-10-31 12:13:02] local.DEBUG: SearchRuleEngine:: done processing all rules!  
[2023-10-31 12:13:02] local.DEBUG: FireflyIII\Handlers\Events\UpdatedGroupEventHandler::triggerWebhooks  
[2023-10-31 12:13:02] local.DEBUG: FireflyIII\Generator\Webhook\StandardMessageGenerator::generateMessages  
[2023-10-31 12:13:02] local.DEBUG: StandardMessageGenerator will generate messages for 1 object(s) and 0 webhook(s).  
[2023-10-31 12:13:02] local.DEBUG: Now in StandardMessageGenerator::run  
[2023-10-31 12:13:02] local.DEBUG: Done with StandardMessageGenerator::run  
[2023-10-31 12:13:02] local.DEBUG: Now in FireflyIII\Handlers\Events\WebhookEventHandler::sendWebhookMessages  
[2023-10-31 12:13:02] local.DEBUG: Found 0 webhook message(s) ready to be send.  
[2023-10-31 12:13:02] local.DEBUG: Now in FireflyIII\Support\Request\ChecksLogin::authorize  
[2023-10-31 12:13:02] local.DEBUG: Request class has no acceptedRoles array  
[2023-10-31 12:13:02] local.DEBUG: Now in FireflyIII\Api\V1\Controllers\Models\Attachment\StoreController::store  
[2023-10-31 12:13:09] local.DEBUG: Now in FireflyIII\Models\TransactionGroup::routeBinder("4")  
[2023-10-31 12:13:09] local.DEBUG: User authenticated as test@test.com  
...

I don't know where else to poke at it, any ideas?

JC5 commented 10 months ago

This is the underlying library: https://github.com/thephpleague/flysystem

I'm checking them out for possible NFS related errors, but so far I got nothing. I added some debug to the latest develop container, so if you do docker logs -f [container] you should be able to see it.

The upload routine creates a temp file before it writes to disk, but it seems that part works as expected.

GregSutcliffe commented 10 months ago

Thanks @JC5, I'll check that out later on today. I added a whole bunch of debug to the various calls in StoreController and AttachmentHelper, and didn't find a whole lot - except that the "size" attribute in StoreController::transform seems to always be zero, even for files that get written correctly. Might be a false-flag, but figured I'd pass it on.

JC5 commented 10 months ago

Do you have some log entries?

GregSutcliffe commented 10 months ago

Sadly not, for the new container anyway. I've updated it to latest develop and set APP_DEBUG=true in the container environment, but it doesn't seem to have helped. Here's the /debug for me adding a PDF to en existing transaction just now:

Debug information generated at 2023-11-05 15:35:30 for Firefly III version v6.0.30.

System information
Item	Value
Firefly III	v6.0.30 / v2.0.11 / 21 (exp. 21)
PHP version	8.2.12 / apache2handler / Linux
BCscale	12
Error reporting	Display: Off, reporting: ALL errors
Max upload	67108864 (64 MB)
Database drivers	mysql, *pgsql*, sqlite,
Docker build	#760, base #40

Firefly III information
Item	Value
Timezone	UTC + Europe/London
App environment	local, debug: true
Layout	v1
Logging	info, stack / (empty)
Cache driver	file
Default language and locale	en_US + equal
Trusted proxies
Login provider & user guard	eloquent / web
Login headers	N/A + N/A
Stateful domains
Last cron job	never (never)
Mailer	log

User-specific information
Item	Value
User	#1 of 1
User flags	:credit_card: :wrench: :email:
Session start	2023-10-06 00:00:00
Session end	2023-11-05 23:59:59
View range	last30
User language	en_GB
User locale	en_GB
Locale(s) supported	en_GB.utf8: :white_check_mark: en_GB.UTF-8: :white_check_mark:
User agent	Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/119.0

Truncated from this point <----|[2023-11-05 15:35:14] local.INFO: Account info is valid, now update.  
[2023-11-05 15:35:14] local.INFO: Not enough info to update foreign currency info.

(I also see VERSION=develop in env inside the container too)

If you mean for the size logging I mentioned above, I can get that, and say where I put the log statements, sure.

JC5 commented 9 months ago

Could you enable debug mode so all log entries are captured?

https://docs.firefly-iii.org/firefly-iii/faq/other/#how-do-i-enable-debug-mode

GregSutcliffe commented 9 months ago

Ugh, I set APP_DEBUG and missed APP_LOG_LEVEL - I knew those logs didn't look right. Updated the container env, and uploaded another PDF, here's the log:

Truncated from this point <----|ent_date":null,"invoice_date":null,"tags":["cafe","Data Import on 2023-11-14 @ 17:31"],"amount":"23.450000000000","foreign_amount":"0"}],"apply_rules":true,"fire_webhooks":true} 
[2023-11-15 22:03:45] local.DEBUG: Will now update journal #221 (only journal in group #220)  
[2023-11-15 22:03:45] local.DEBUG: Now in FireflyIII\Services\Internal\Update\GroupUpdateService::updateTransactionJournal  
[2023-11-15 22:03:45] local.DEBUG: Now in FireflyIII\Services\Internal\Update\JournalUpdateService::update  
[2023-11-15 22:03:45] local.DEBUG: Now in JournalUpdateService for journal #221.  
[2023-11-15 22:03:45] local.DEBUG: Now in hasValidSourceAccount().  
[2023-11-15 22:03:45] local.DEBUG: Now in getExpectedType()  
[2023-11-15 22:03:45] local.DEBUG: Expected type (new or unchanged) is Withdrawal  
[2023-11-15 22:03:45] local.DEBUG: Transaction type for validator is now "Withdrawal".  
[2023-11-15 22:03:45] local.DEBUG: Now in AccountValidator::validateSource() {"id":1} 
[2023-11-15 22:03:45] local.DEBUG: Now in validateWithdrawalSource {"id":1} 
[2023-11-15 22:03:45] local.DEBUG: Now in findExistingAccount {"id":1} 
[2023-11-15 22:03:45] local.DEBUG: The search will be reversed!  
[2023-11-15 22:03:45] local.DEBUG: ID: Found Asset account account #1 ("redacted", IBAN "redacted")  
[2023-11-15 22:03:45] local.DEBUG: AccountValidator source is set to #1: "redacted" (Asset account)  
[2023-11-15 22:03:45] local.DEBUG: Valid source account!  
[2023-11-15 22:03:45] local.DEBUG: hasValidSourceAccount(1, "redacted") will return true  
[2023-11-15 22:03:45] local.DEBUG: Now in hasValidDestinationAccount().  
[2023-11-15 22:03:45] local.DEBUG: Now in getExpectedType()  
[2023-11-15 22:03:45] local.DEBUG: Expected type (new or unchanged) is Withdrawal  
[2023-11-15 22:03:45] local.DEBUG: Transaction type for validator is now "Withdrawal".  
[2023-11-15 22:03:45] local.DEBUG: Now in getValidSourceAccount().  
[2023-11-15 22:03:45] local.DEBUG: Now in getExpectedType()  
[2023-11-15 22:03:45] local.DEBUG: Now in getAccount(source) {"id":1,"name":"redacted","iban":null,"number":null,"bic":null} 
[2023-11-15 22:03:45] local.DEBUG: Transaction = Withdrawal, source account should be in: Asset account, Loan, Debt, Mortgage. Direction is source.  
[2023-11-15 22:03:45] local.DEBUG: Found "account_id" object: #1, "redacted" of type Asset account (1)  
[2023-11-15 22:03:45] local.DEBUG: Already have account #1 ("redacted"), return that.  
[2023-11-15 22:03:45] local.DEBUG: Already have account #1 ("redacted"), return that.  
[2023-11-15 22:03:45] local.DEBUG: Already have account #1 ("redacted"), return that.  
[2023-11-15 22:03:45] local.DEBUG: getValidSourceAccount() will return #1 ("redacted")  
[2023-11-15 22:03:45] local.DEBUG: Now in AccountValidator::validateDestination() {"id":32,"name":"Cafe"} 
[2023-11-15 22:03:45] local.DEBUG: Now in validateWithdrawalDestination() {"id":32,"name":"Cafe"} 
[2023-11-15 22:03:45] local.DEBUG: Source type can be:  ["Expense account","Loan","Debt","Mortgage","Cash account"] 
[2023-11-15 22:03:45] local.DEBUG: AccountValidator destination is set to #32: "Cafe" (Expense account)  
[2023-11-15 22:03:45] local.DEBUG: hasValidDestinationAccount(32, "Cafe") will return true  
[2023-11-15 22:03:45] local.INFO: Account info is valid, now update.  
[2023-11-15 22:03:45] local.DEBUG: Now in getValidSourceAccount().  
[2023-11-15 22:03:45] local.DEBUG: Now in getExpectedType()  
[2023-11-15 22:03:45] local.DEBUG: Now in getAccount(source) {"id":1,"name":"redacted","iban":null,"number":null,"bic":null} 
[2023-11-15 22:03:45] local.DEBUG: Transaction = Withdrawal, source account should be in: Asset account, Loan, Debt, Mortgage. Direction is source.  
[2023-11-15 22:03:45] local.DEBUG: Found "account_id" object: #1, "redacted" of type Asset account (1)  
[2023-11-15 22:03:45] local.DEBUG: Already have account #1 ("redacted"), return that.  
[2023-11-15 22:03:45] local.DEBUG: Already have account #1 ("redacted"), return that.  
[2023-11-15 22:03:45] local.DEBUG: Already have account #1 ("redacted"), return that.  
[2023-11-15 22:03:45] local.DEBUG: getValidSourceAccount() will return #1 ("redacted")  
[2023-11-15 22:03:45] local.DEBUG: Now in getValidDestinationAccount().  
[2023-11-15 22:03:45] local.DEBUG: Now in getExpectedType()  
[2023-11-15 22:03:45] local.DEBUG: Expected type (new or unchanged) is Withdrawal  
[2023-11-15 22:03:45] local.DEBUG: Now in getAccount(destination) {"id":32,"name":"Cafe","iban":null,"number":null,"bic":null} 
[2023-11-15 22:03:45] local.DEBUG: Transaction = Withdrawal, destination account should be in: Loan, Debt, Mortgage, Expense account, Cash account. Direction is destination.  
[2023-11-15 22:03:45] local.DEBUG: Found "account_id" object: #32, "Cafe" of type Expense account (1)  
[2023-11-15 22:03:45] local.DEBUG: Already have account #32 ("Cafe"), return that.  
[2023-11-15 22:03:45] local.DEBUG: Already have account #32 ("Cafe"), return that.  
[2023-11-15 22:03:45] local.DEBUG: Already have account #32 ("Cafe"), return that.  
[2023-11-15 22:03:45] local.DEBUG: getSourceTransaction: -23.450000000000  
[2023-11-15 22:03:45] local.DEBUG: Will set source to #1 ("redacted")  
[2023-11-15 22:03:45] local.DEBUG: Will set dest to #32 ("Cafe")  
[2023-11-15 22:03:45] local.DEBUG: Now in updateType()  
[2023-11-15 22:03:45] local.DEBUG: Trying to change journal #221 from a Withdrawal to a withdrawal.  
[2023-11-15 22:03:45] local.DEBUG: Changed transaction type!  
[2023-11-15 22:03:45] local.DEBUG: Will not store event log because before and after are the same.  
[2023-11-15 22:03:45] local.DEBUG: Updated description  
[2023-11-15 22:03:45] local.DEBUG: Create date value from string "2023-11-13 00:00:00".  
[2023-11-15 22:03:45] local.DEBUG: Will not store event log because before and after Carbon values are the same.  
[2023-11-15 22:03:45] local.DEBUG: Updated date  
[2023-11-15 22:03:45] local.DEBUG: Will update category.  
[2023-11-15 22:03:45] local.DEBUG: Now in findCategory()  
[2023-11-15 22:03:45] local.DEBUG: Searching for category with ID #0...  
[2023-11-15 22:03:45] local.DEBUG: Searching for category with name Eating Out...  
[2023-11-15 22:03:45] local.DEBUG: Found category #4: Eating Out  
[2023-11-15 22:03:45] local.DEBUG: Found category result is null? false  
[2023-11-15 22:03:45] local.DEBUG: Link category #4 to journal #221  
[2023-11-15 22:03:45] local.DEBUG: Will update budget.  
[2023-11-15 22:03:45] local.DEBUG: Now in findBudget()  
[2023-11-15 22:03:45] local.DEBUG: Searching for budget with ID #0...  
[2023-11-15 22:03:45] local.DEBUG: Found result is null? true  
[2023-11-15 22:03:45] local.DEBUG: Will update tags.  
[2023-11-15 22:03:45] local.DEBUG: Now in storeTags() ["cafe","Data Import on 2023-11-14 @ 17:31"] 
[2023-11-15 22:03:45] local.DEBUG: Start of loop.  
[2023-11-15 22:03:45] local.DEBUG: Now at tag "cafe"  
[2023-11-15 22:03:45] local.DEBUG: Now in TagFactory::findOrCreate("cafe")  
[2023-11-15 22:03:45] local.DEBUG: Tag exists (#14), return it.  
[2023-11-15 22:03:45] local.DEBUG: Now at tag "Data Import on 2023-11-14 @ 17:31"  
[2023-11-15 22:03:45] local.DEBUG: Now in TagFactory::findOrCreate("Data Import on 2023-11-14 @ 17:31")  
[2023-11-15 22:03:45] local.DEBUG: Tag exists (#55), return it.  
[2023-11-15 22:03:45] local.DEBUG: End of loop.  
[2023-11-15 22:03:45] local.DEBUG: Total nr. of tags: 2 ["cafe","Data Import on 2023-11-14 @ 17:31"] 
[2023-11-15 22:03:45] local.DEBUG: Stored notes for journal #221  
[2023-11-15 22:03:45] local.DEBUG: Meta string fields are present.  
[2023-11-15 22:03:45] local.DEBUG: Field "internal_reference" is present (""), try to update it.  
[2023-11-15 22:03:45] local.DEBUG: Field "external_url" is present (""), try to update it.  
[2023-11-15 22:03:45] local.DEBUG: Meta date fields are present.  
[2023-11-15 22:03:45] local.DEBUG: Field "interest_date" is present (""), try to update it.  
[2023-11-15 22:03:45] local.DEBUG: Field "book_date" is present (""), try to update it.  
[2023-11-15 22:03:45] local.DEBUG: Field "process_date" is present (""), try to update it.  
[2023-11-15 22:03:45] local.DEBUG: Field "due_date" is present (""), try to update it.  
[2023-11-15 22:03:45] local.DEBUG: Field "payment_date" is present (""), try to update it.  
[2023-11-15 22:03:45] local.DEBUG: Field "invoice_date" is present (""), try to update it.  
[2023-11-15 22:03:45] local.DEBUG: Now in findCurrencyNull()  
[2023-11-15 22:03:45] local.DEBUG: Final result: GBP  
[2023-11-15 22:03:45] local.DEBUG: getSourceTransaction: -23.450000000000  
[2023-11-15 22:03:45] local.DEBUG: Updated currency to #3 (GBP)  
[2023-11-15 22:03:45] local.DEBUG: Now in FireflyIII\Services\Internal\Update\JournalUpdateService::updateAmount  
[2023-11-15 22:03:45] local.DEBUG: Amount is now "23.450000000000"  
[2023-11-15 22:03:45] local.DEBUG: Now in getAmount("23.450000000000")  
[2023-11-15 22:03:45] local.DEBUG: getSourceTransaction: -23.450000000000  
[2023-11-15 22:03:45] local.DEBUG: Updated amount to "23.450000000000"  
[2023-11-15 22:03:45] local.DEBUG: Foreign amount is 0.0, return NULL.  
[2023-11-15 22:03:45] local.DEBUG: getSourceTransaction: -23.450000000000  
[2023-11-15 22:03:45] local.DEBUG: Now in findCurrencyNull()  
[2023-11-15 22:03:45] local.DEBUG: Searching for currency with code ...  
[2023-11-15 22:03:45] local.DEBUG: Foreign amount is "0" so remove foreign amount info.  
[2023-11-15 22:03:45] local.INFO: Not enough info to update foreign currency info.  
[2023-11-15 22:03:45] local.DEBUG: Add local operator for journal(s): 221  
[2023-11-15 22:03:45] local.DEBUG: Will filter getRuleGroupsWithRules on "update-journal".  
[2023-11-15 22:03:45] local.DEBUG: Now filtering group #1  
[2023-11-15 22:03:45] local.DEBUG: Now filtering group #2  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #2  
[2023-11-15 22:03:45] local.DEBUG: Rule #2 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #21  
[2023-11-15 22:03:45] local.DEBUG: Rule #21 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #5  
[2023-11-15 22:03:45] local.DEBUG: Rule #5 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #3  
[2023-11-15 22:03:45] local.DEBUG: Rule #3 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #8  
[2023-11-15 22:03:45] local.DEBUG: Rule #8 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering group #3  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #4  
[2023-11-15 22:03:45] local.DEBUG: Rule #4 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #7  
[2023-11-15 22:03:45] local.DEBUG: Rule #7 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #6  
[2023-11-15 22:03:45] local.DEBUG: Rule #6 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #10  
[2023-11-15 22:03:45] local.DEBUG: Rule #10 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #31  
[2023-11-15 22:03:45] local.DEBUG: Rule #31 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #9  
[2023-11-15 22:03:45] local.DEBUG: Rule #9 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #12  
[2023-11-15 22:03:45] local.DEBUG: Rule #12 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #14  
[2023-11-15 22:03:45] local.DEBUG: Rule #14 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #18  
[2023-11-15 22:03:45] local.DEBUG: Rule #18 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #17  
[2023-11-15 22:03:45] local.DEBUG: Rule #17 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #19  
[2023-11-15 22:03:45] local.DEBUG: Rule #19 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #20  
[2023-11-15 22:03:45] local.DEBUG: Rule #20 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #26  
[2023-11-15 22:03:45] local.DEBUG: Rule #26 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #23  
[2023-11-15 22:03:45] local.DEBUG: Rule #23 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #30  
[2023-11-15 22:03:45] local.DEBUG: Rule #30 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #28  
[2023-11-15 22:03:45] local.DEBUG: Rule #28 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Now filtering rule #27  
[2023-11-15 22:03:45] local.DEBUG: Rule #27 does not trigger on update-journal, do not include it.  
[2023-11-15 22:03:45] local.DEBUG: Add extra operator:  {"type":"journal_id","value":"221"} 
[2023-11-15 22:03:45] local.DEBUG: FireflyIII\TransactionRules\Engine\SearchRuleEngine::setRuleGroups  
[2023-11-15 22:03:45] local.DEBUG: Adding a rule group to the SearchRuleEngine: #1 ("Default rules")  
[2023-11-15 22:03:45] local.DEBUG: Adding a rule group to the SearchRuleEngine: #2 ("Bill Rules")  
[2023-11-15 22:03:45] local.DEBUG: Adding a rule group to the SearchRuleEngine: #3 ("Nordigen Cleanup")  
[2023-11-15 22:03:45] local.DEBUG: SearchRuleEngine::fire()!  
[2023-11-15 22:03:45] local.DEBUG: SearchRuleEngine:: found 3 rule group(s) to fire.  
[2023-11-15 22:03:45] local.DEBUG: Going to fire group #1 with 0 rule(s)  
[2023-11-15 22:03:45] local.DEBUG: Going to fire group #2 with 0 rule(s)  
[2023-11-15 22:03:45] local.DEBUG: Going to fire group #3 with 0 rule(s)  
[2023-11-15 22:03:45] local.DEBUG: SearchRuleEngine:: done processing all rules!  
[2023-11-15 22:03:45] local.DEBUG: FireflyIII\Handlers\Events\UpdatedGroupEventHandler::triggerWebhooks  
[2023-11-15 22:03:45] local.DEBUG: FireflyIII\Generator\Webhook\StandardMessageGenerator::generateMessages  
[2023-11-15 22:03:45] local.DEBUG: StandardMessageGenerator will generate messages for 1 object(s) and 0 webhook(s).  
[2023-11-15 22:03:45] local.DEBUG: Now in StandardMessageGenerator::run  
[2023-11-15 22:03:45] local.DEBUG: Done with StandardMessageGenerator::run  
[2023-11-15 22:03:45] local.DEBUG: Now in FireflyIII\Handlers\Events\WebhookEventHandler::sendWebhookMessages  
[2023-11-15 22:03:45] local.DEBUG: Found 0 webhook message(s) ready to be send.  
[2023-11-15 22:03:46] local.DEBUG: Now in FireflyIII\Support\Request\ChecksLogin::authorize  
[2023-11-15 22:03:46] local.DEBUG: Request class has no acceptedRoles array  
[2023-11-15 22:03:46] local.DEBUG: Now in FireflyIII\Api\V1\Controllers\Models\Attachment\StoreController::store  
[2023-11-15 22:03:46] local.DEBUG: Now in FireflyIII\Helpers\Attachments\AttachmentHelper::saveAttachmentFromApi  
[2023-11-15 22:03:46] local.DEBUG: Path is /tmp/phpb2oEAN  
[2023-11-15 22:03:46] local.DEBUG: Wrote 211510 bytes to temp file.  
[2023-11-15 22:03:46] local.DEBUG: Found mime "application/pdf" in file "/tmp/phpb2oEAN"  
[2023-11-15 22:03:46] local.DEBUG: Write file to disk in file named "at-18.data"  
[2023-11-15 22:03:53] local.DEBUG: Done!  
[2023-11-15 22:03:53] local.DEBUG: Now in FireflyIII\Models\TransactionGroup::routeBinder("220")  
[2023-11-15 22:03:53] local.DEBUG: User authenticated as user@redacted  
[2023-11-15 22:03:53] local.DEBUG: Found group #220.  
[2023-11-15 22:04:02] local.DEBUG: Trying to set en_GB.utf8  
[2023-11-15 22:04:02] local.DEBUG: Trying to set en_GB.UTF-8

So, it appears to write the tempfile, as you said (the file is indeed 211510 bytes, according to stat), but sadly at-18.data is again zero-length. On a whim, I also checked from a shell in the container that www-data could write files to /tmp and move them to upload/ - it can:

su -s /bin/bash www-data -c "echo foo > /tmp/test"
su -s /bin/bash www-data -c "mv /tmp/test /var/www/html/storage/upload/"
cat ./upload/test
  foo

I'm really stumped here - thanks again for your help so far!

JC5 commented 9 months ago

Inside the container, the user may be www-data, but that doesn't have to match with the outside world. Who's the owner (UID!) of the temp file, and which user is that on the host system?

GregSutcliffe commented 9 months ago

So the UIDs are fine, but in checking they were consistent on the NFS server, I noticed that the lockd daemon was complaining!

Digging further using this idea to test the file locking confirmed that file locking was not working from inside the container. After some digging around with my NFS config I got the issue resolved, and (unsurprisingly) file attachments are now created correctly.

I guess PSQL isn't using file locking, which is why I was mistaken when I said "NFS is working fine because my DB works" - it was chance that the DB was being written correctly.

Thanks for persevering with me, and apologies for using up your time!

JC5 commented 9 months ago

Not a problem, I'm glad you found it!

github-actions[bot] commented 9 months ago

Hi there! This is an automatic reply. Share and enjoy

This issue is now 🔒 closed. Please be aware that closed issues are not monitored by the developer of Firefly III.

If the original bug is not actually fixed, please open a new issue. Refer to this issue for clarity.
Follow-up questions must be posted in a new discussion
Further replies to this issue may get no response.

If there is more to discuss, please open a new issue or discussion.

Thank you for your contributions.

firefly-iii / firefly-iii