Cannot add feed (user id is null)

[guidopetri]

I'm getting an error on adding a feed where a user id seems to be null:

2023-08-06 00:56:52 - ActiveRecord::NotNullViolation - PG::NotNullViolation: ERROR:  null value in column "user_id" of relation "feeds" violates not-null constraint
DETAIL:  Failing row contains (165, Data Colada, http://datacolada.org/feed, 2023-08-05 00:56:52.229693, 2023-08-06 00:56:52.234082, 2023-08-06 00:56:52.234082, null, null, null).
:

I think this might be due to my migration process from a very old postgres db (sorry). Any idea how I can fix this manually? Can I set a userid somewhere in the db/insert a row somewhere that will fix this?

[mockdeep]

@guidopetri thanks for letting me know! Did you run the migrations with rails db:migrate? Can you tell me which commit you are on?

[guidopetri]

I don't think I ever did that manually, no. I'm not sure how to use it exactly - I'm bashing into the container but running rails db:migrate just returns the man/help for rails new, apparently:

stringer@928cf58af2ad:/app$ rails db:migrate
Usage:
  rails new APP_PATH [options]

Options:
   ...

Same output for bundle exec rails db:migrate. That being said, when I set this up a few weeks back, I do remember that (some of) the migrations ran successfully (so much so that I think I was the one who raised this issue); though when I run the following this is what I get:

stringer_live=# select * from schema_migrations;
    version
----------------
 20130409010818
 20130409010826
 20130412185253
...
 20221206231914
 20230120222742
 20230221233057
 20230223045525
(26 rows)

so it appears I don't have it fully migrated.

I'm using this commit to build the image, i.e. I took 155f3c2 and modified the Dockerfile for ARM back before we modified that.

[mockdeep]

@guidopetri you'll need to be in the application directory to run the command. When you type ls, you should see the same folders as the repo. You may want to run bundle to make sure your Ruby dependencies are up to date, and then bundle exec rails db:migrate. It looks like you're using a slightly out of date version of Stringer, but it should work regardless.

I'm a little surprised to see this error, though. Worst case, if we manage to get the migrations to run and you're still seeing the error, you may need to update to the latest version. I haven't gotten around to publishing a new docker image, but hopefully I'll manage it in the next week or so.

[guidopetri]

Indeed, I was in the application directory. I didn't run bundle by itself but can try next time.

I'll try updating to the latest version this weekend or next and I'll ping back if it's still not working. I'll probably still need to build the image myself (unless you build the arm64 version heh) so don't worry about publishing a new docker image (for my sake, at least).

[guidopetri]

I tried again and ran bundle and it gave me a green light, but bundle exec rails db:migrate still didn't work. :(

I tried updating the image to base off of 2c7cd3e, but got this:

From the logs below, I'm guessing the error is some misconfiguration in cluster mode / worker count:

Warning: You specified code to run in a `on_worker_boot` block, but Puma is not configured to run in cluster mode (worker count > 0 ), so your `on_worker_boot` block did not run

but I don't know how to fix it (and it seems unrelated to the original issue of not being able to add feeds). Re-reading through the original issue, I realized I never looked at the feeds or users tables. Here's the output:

stringer=# \d feeds
                                         Table "public.feeds"
    Column    |            Type             | Collation | Nullable |              Default
--------------+-----------------------------+-----------+----------+-----------------------------------
 id           | integer                     |           | not null | nextval('feeds_id_seq'::regclass)
 name         | character varying           |           |          |
 url          | text                        |           |          |
 last_fetched | timestamp without time zone |           |          |
 created_at   | timestamp without time zone |           | not null |
 updated_at   | timestamp without time zone |           | not null |
 status       | integer                     |           |          |
 group_id     | integer                     |           |          |
 user_id      | bigint                      |           |          |
Indexes:
    "feeds_pkey" PRIMARY KEY, btree (id)
    "index_feeds_on_url" UNIQUE, btree (url)
    "index_feeds_on_user_id" btree (user_id)
Foreign-key constraints:
    "fk_rails_36f9216dc2" FOREIGN KEY (user_id) REFERENCES users(id)

stringer=# select * from feeds limit 1;
 id |        name         |                  url                  |        last_fetched        |         created_at         |        updated_at         | status | group_id | user_id
----+---------------------+---------------------------------------+----------------------------+----------------------------+---------------------------+--------+----------+---------
  4 | The Happy Broadcast | https://www.thehappybroadcast.com/rss | 2023-07-01 23:41:34.141708 | 2023-07-02 23:41:34.147286 | 2023-07-02 23:41:37.53017 |      2 |          |
(1 row)

stringer=# select id, created_at, updated_at from users; --removed sensitive information columns `password_digest` and `api_key`
 id |         created_at         |         updated_at
----+----------------------------+----------------------------
  1 | 2023-07-02 23:41:15.521086 | 2023-07-02 23:41:15.521086
(1 row)

so it appears that there's a FK constraint on user_id but all my feeds' user_id is null, even though my user does have id 1.

Full logs:

2023-08-21 01:36:54,671 INFO supervisord started with pid 1
2023-08-21 01:36:55,681 INFO spawned: 'cron' with pid 8
2023-08-21 01:36:55,693 INFO spawned: 'puma' with pid 9
2023-08-21 01:36:55,737 DEBG 'cron' stderr output:
time="2023-08-21T01:36:55Z" level=info msg="read crontab: /app/crontab"

2023-08-21 01:36:56,739 INFO success: cron entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-08-21 01:36:56,740 INFO success: puma entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2023-08-21 01:37:11,918 DEBG 'puma' stdout output:
Warning: You specified code to run in a `before_fork` block, but Puma is not configured to run in cluster mode (worker count > 0 ), so your `before_fork` block did not run

2023-08-21 01:37:11,919 DEBG 'puma' stdout output:
Warning: You specified code to run in a `on_worker_boot` block, but Puma is not configured to run in cluster mode (worker count > 0 ), so your `on_worker_boot` block did not run
Warning: You specified code to run in a `on_worker_shutdown` block, but Puma is not configured to run in cluster mode (worker count > 0 ), so your `on_worker_shutdown` block did not run

2023-08-21 01:37:11,928 DEBG 'puma' stdout output:
[9] Puma starting in cluster mode...
[9] * Puma version: 6.3.1 (ruby 3.2.2-p53) ("Mugi No Toki Itaru")

2023-08-21 01:37:11,929 DEBG 'puma' stdout output:
[9] *  Min threads: 2
[9] *  Max threads: 2
[9] *  Environment: production
[9] *   Master PID: 9
[9] *      Workers: 2
[9] *     Restarts: (✔) hot (✖) phased
[9] * Preloading application

2023-08-21 01:37:23,955 DEBG 'puma' stdout output:
[9] * Listening on http://0.0.0.0:5000

2023-08-21 01:37:23,959 DEBG 'puma' stdout output:
[9] ! WARNING: Detected 4 Thread(s) started in app boot:

2023-08-21 01:37:23,969 DEBG 'puma' stdout output:
[9] ! #<Thread:0x0000007f919c3900@worker-1 /usr/local/bundle/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:332 sleep> - /usr/local/bundle/gems/zeitwerk-2.6.11/lib/zeitwerk/kernel.rb:38:in `require'

2023-08-21 01:37:23,970 DEBG 'puma' stdout output:
[9] ! #<Thread:0x0000007f9194fcd0@io-worker-1 /usr/local/bundle/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:332 sleep_forever> - <internal:thread_sync>:18:in `pop'
[9] ! #<Thread:0x0000007f91942850@worker-1 /usr/local/bundle/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:332 sleep> - /usr/local/bundle/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:53:in `sleep'

2023-08-21 01:37:23,974 DEBG 'puma' stdout output:
[9] ! #<Thread:0x0000007f9195f770@GoodJob::Scheduler(queues=* max_threads=5)-worker-1 /usr/local/bundle/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:332 sleep_forever> - /usr/local/bundle/gems/activerecord-7.0.7/lib/active_record/log_subscriber.rb:14:in `runtime'

2023-08-21 01:37:23,977 DEBG 'puma' stdout output:
[9] Use Ctrl-C to stop

2023-08-21 01:37:25,419 DEBG 'puma' stdout output:
[9] - Worker 0 (PID: 25) booted in 0.05s, phase: 0

2023-08-21 01:37:25,434 DEBG 'puma' stdout output:
[9] - Worker 1 (PID: 26) booted in 0.05s, phase: 0

2023-08-21 01:40:00,001 DEBG 'cron' stderr output:
time="2023-08-21T01:40:00Z" level=info msg=starting iteration=0 job.command="cd /app && bundle exec rake fetch_feeds" job.position=0 job.schedule="*/5 * * * *"

[mockdeep]

Hmm, that's really odd. Let's focus on getting the migrations working first. Can you share the output you see when you run rails db:migrate? There should be a stack trace with an error that shows which migration it failed during.

[mockdeep]

If you'd rather, we can set up a pairing session and do a screen share. My email is in my profile, so feel free to send me a message.

[guidopetri]

Closure for the issue: I had, indeed, not run all migrations, and I was using an old version of the application which wasn't on rails yet, so that's why I wasn't able to run rails db:migrate. After upgrading, we ran into some issues with assets not loading (issue to be opened), but precompiling them fixed it.

Thanks again @mockdeep !