ruby - Rails won't save to database after tiny model manipulation -

i'm coding first rails app @ moment , can't resolve annoying error.

what want do: app connected user's dropbox account. user can specify path in app looks audio files. these audio files shall downloaded, metadata, path, etc saved song model in database, belongs_to corresponding user.

i implemented method indexes dropbox folder , saves filename , direct link few weeks ago. added line saves entire dropbox path database , of sudden nothing saved anymore.

this song model looks like:

require "dropbox_helper" require "open-uri"  class song < activerecord::base   belongs_to :user   attr_accessible :artist, :expiration, :is_cached, :length, :dropbox_link, :local_path, :title, :dropbox_path    validates_presence_of :title, :is_cached, :dropbox_link, :dropbox_path   #validates :dropbox_path, :uniqueness => true    def self.fetch_basic_songdata(user)     logger.info "++++debug: song#fetch_basic_songdata started"     dbh = dropboxhelper.new(user.dropbox_access_key, user.dropbox_access_secret, user.dropbox_folder)     logger.info "++++debug: dropboxhelper initialized"     songs_metadata = dbh.generate_audio_index     logger.info "++++debug: metadata generated"     #logger.debug songs_metadata.inspect     songs_metadata.each |smd|       logger.info "preparing song #{smd['path']} saving"       songdata = dbh.song_data(smd)       user.songs.create |s|         s.title = songdata['filename']         s.dropbox_path = songdata['path']         s.dropbox_link = songdata['link']         s.is_cached = false         logger.info "song #{s[:title]} generated"         logger.info "song #{s[:title]} saved data base"       end     end   end  end 

now when call song.fetch_basic_songdata(user.find(1)) in rails console, prints following:

irb(main):002:0> song.fetch_basic_songdata(user.find(1))   user load (59.4ms)  select "users".* "users" "users"."id" = ? limit 1  [["id", 1]] song#fetch_basic_songdata started preparing song /audiomixer/01 - paradise.mp3 saving    (0.1ms)  begin transaction song 01 - paradise.mp3 generated song 01 - paradise.mp3 saved data base    (0.1ms)  commit transaction preparing song /audiomixer/02 - weirdo.mp3 saving    (0.1ms)  begin transaction song 02 - weirdo.mp3 generated song 02 - weirdo.mp3 saved data base    (0.2ms)  commit transaction preparing song /audiomixer/03 - when was.mp3 saving    (0.1ms)  begin transaction song 03 - when was.mp3 generated song 03 - when was.mp3 saved data base    (0.1ms)  commit transaction preparing song /audiomixer/04 - broken promise.mp3 saving    (0.2ms)  begin transaction song 04 - broken promise.mp3 generated song 04 - broken promise.mp3 saved data base    (0.1ms)  commit transaction preparing song /audiomixer/05 - way of life.mp3 saving    (0.1ms)  begin transaction song 05 - way of life.mp3 generated song 05 - way of life.mp3 saved data base    (0.1ms)  commit transaction preparing song /audiomixer/06 - bizarre love triangle.mp3 saving    (0.1ms)  begin transaction song 06 - bizarre love triangle.mp3 generated song 06 - bizarre love triangle.mp3 saved data base    (0.1ms)  commit transaction preparing song /audiomixer/07 - day long.mp3 saving    (0.1ms)  begin transaction song 07 - day long.mp3 generated song 07 - day long.mp3 saved data base    (0.1ms)  commit transaction preparing song /audiomixer/08 - angel dust.mp3 saving    (0.1ms)  begin transaction song 08 - angel dust.mp3 generated song 08 - angel dust.mp3 saved data base    (0.1ms)  commit transaction preparing song /audiomixer/09 - every little counts.mp3 saving    (0.1ms)  begin transaction song 09 - every little counts.mp3 generated song 09 - every little counts.mp3 saved data base    (0.1ms)  commit transaction preparing song /audiomixer/10 - state of nation.mp3 saving    (0.1ms)  begin transaction song 10 - state of nation.mp3 generated song 10 - state of nation.mp3 saved data base    (0.0ms)  commit transaction => [#<dropbox::api::file bytes=3710598 client_mtime="fri, 23 jul 2010 00:09:30 +0000" icon="page_white_sound" is_dir=false mime_type="audio/mpeg" modified="mon, 22 apr 2013 12:27:54 +0000" path="/audiomixer/01 - paradise.mp3" rev="4b6ad8fc0010df0f" revision=1265293564 root="dropbox" size="3.5 mb" thumb_exists=false>, #<dropbox::api::file bytes=3731496 client_mtime="fri, 23 jul 2010 00:09:30 +0000" icon="page_white_sound" is_dir=false mime_type="audio/mpeg" modified="mon, 22 apr 2013 12:27:54 +0000" path="/audiomixer/02 - weirdo.mp3" rev="4b6ad8fd0010df0f" revision=1265293565 root="dropbox" size="3.6 mb" thumb_exists=false>, #<dropbox::api::file bytes=3620319 client_mtime="sun, 10 jan 2010 19:50:28 +0000" icon="page_white_sound" is_dir=false mime_type="audio/mpeg" modified="mon, 22 apr 2013 12:27:54 +0000" path="/audiomixer/03 - when was.mp3" rev="4b6ad8fa0010df0f" revision=1265293562 root="dropbox" size="3.5 mb" thumb_exists=false>, #<dropbox::api::file bytes=3645815 client_mtime="sun, 10 jan 2010 19:50:28 +0000" icon="page_white_sound" is_dir=false mime_type="audio/mpeg" modified="mon, 22 apr 2013 12:27:54 +0000" path="/audiomixer/04 - broken promise.mp3" rev="4b6ad8fb0010df0f" revision=1265293563 root="dropbox" size="3.5 mb" thumb_exists=false>, #<dropbox::api::file bytes=3954295 client_mtime="sat, 20 apr 2013 07:09:30 +0000" icon="page_white_sound" is_dir=false mime_type="audio/mpeg" modified="mon, 22 apr 2013 12:27:54 +0000" path="/audiomixer/05 - way of life.mp3" rev="4b6ad8fe0010df0f" revision=1265293566 root="dropbox" size="3.8 mb" thumb_exists=false>, #<dropbox::api::file bytes=4199193 client_mtime="sun, 10 jan 2010 19:50:28 +0000" icon="page_white_sound" is_dir=false mime_type="audio/mpeg" modified="mon, 22 apr 2013 12:27:54 +0000" path="/audiomixer/06 - bizarre love triangle.mp3" rev="4b6ad8ff0010df0f" revision=1265293567 root="dropbox" size="4 mb" thumb_exists=false>, #<dropbox::api::file bytes=5002092 client_mtime="sun, 10 jan 2010 19:50:28 +0000" icon="page_white_sound" is_dir=false mime_type="audio/mpeg" modified="mon, 22 apr 2013 12:27:54 +0000" path="/audiomixer/07 - day long.mp3" rev="4b6ad9010010df0f" revision=1265293569 root="dropbox" size="4.8 mb" thumb_exists=false>, #<dropbox::api::file bytes=3595686 client_mtime="sat, 20 apr 2013 07:09:31 +0000" icon="page_white_sound" is_dir=false mime_type="audio/mpeg" modified="mon, 22 apr 2013 12:27:54 +0000" path="/audiomixer/08 - angel dust.mp3" rev="4b6ad8f90010df0f" revision=1265293561 root="dropbox" size="3.4 mb" thumb_exists=false>, #<dropbox::api::file bytes=4307888 client_mtime="sat, 20 apr 2013 07:09:32 +0000" icon="page_white_sound" is_dir=false mime_type="audio/mpeg" modified="mon, 22 apr 2013 12:27:54 +0000" path="/audiomixer/09 - every little counts.mp3" rev="4b6ad9000010df0f" revision=1265293568 root="dropbox" size="4.1 mb" thumb_exists=false>, #<dropbox::api::file bytes=6313648 client_mtime="sun, 10 jan 2010 19:50:28 +0000" icon="page_white_sound" is_dir=false mime_type="audio/mpeg" modified="mon, 22 apr 2013 12:27:54 +0000" path="/audiomixer/10 - state of nation.mp3" rev="4b6ad9020010df0f" revision=1265293570 root="dropbox" size="6 mb" thumb_exists=false>] 

to check if saved:

irb(main):003:0> song.all   song load (0.3ms)  select "songs".* "songs"  => [] 

i noticed lines starting logger.info "++++debug:[...]" not printed @ all. before inserted them, logger.info lines below weren't printed. don't behaviour, can of help?

ps: hope information provided sufficient. app's behaviour totally random me, have hard time understanding what's essential problem.

edit: comments! recommended, tried using create!. told me:

irb(main):002:0> song.fetch_basic_songdata(user.find(1))   user load (0.1ms)  select "users".* "users" "users"."id" = ? limit 1  [["id", 1]] ++++debug: song#fetch_basic_songdata started ++++debug: dropboxhelper initialized ++++debug: metadata generated preparing song /audiomixer/01 - paradise.mp3 saving    (0.1ms)  begin transaction song 01 - paradise.mp3 generated song 01 - paradise.mp3 saved data base    (0.2ms)  rollback transaction activerecord::recordinvalid: validation failed: cached can't blank     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/validations.rb:56:in `save!'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/attribute_methods/dirty.rb:33:in `save!'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/transactions.rb:264:in `block in save!'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/transactions.rb:313:in `block in with_transaction_returning_status'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/database_statements.rb:192:in `transaction'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/transactions.rb:208:in `transaction'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/transactions.rb:311:in `with_transaction_returning_status'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/transactions.rb:264:in `save!'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/associations/has_many_association.rb:14:in `insert_record'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/associations/collection_association.rb:436:in `block (2 levels) in create_record'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/associations/collection_association.rb:344:in `add_to_target'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/associations/collection_association.rb:434:in `block in create_record'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/associations/collection_association.rb:149:in `block in transaction'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/connection_adapters/abstract/database_statements.rb:192:in `transaction'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/transactions.rb:208:in `transaction'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/associations/collection_association.rb:148:in `transaction'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/associations/collection_association.rb:433:in `create_record'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/associations/collection_association.rb:123:in `create!'     /var/lib/gems/1.9.1/gems/activerecord-3.2.13/lib/active_record/associations/collection_proxy.rb:46:in `create!'     /home/sloth/audiomixer/app/models/song.rb:21:in `block in fetch_basic_songdata'     /home/sloth/audiomixer/app/models/song.rb:18:in `each'     /home/sloth/audiomixer/app/models/song.rb:18:in `fetch_basic_songdata'     (irb):2     /var/lib/gems/1.9.1/gems/railties-3.2.13/lib/rails/commands/console.rb:47:in `start'     /var/lib/gems/1.9.1/gems/railties-3.2.13/lib/rails/commands/console.rb:8:in `start'     /var/lib/gems/1.9.1/gems/railties-3.2.13/lib/rails/commands.rb:41:in `<top (required)>'     script/rails:6:in `require'     script/rails:6:in ` 

so if interpreted correctly, problem is_cached variable appears blank (empty? nil?). assume being due error happening before s.is_cached = false assignment. ideas how find it?

besides, commented of logger.info lines , added new ones instead. after restarted server, tried again , printed lines commented none of new ones. lack important information rails using old files? i've been doing same things during last weeks , never experienced such weird experience.

you shouldn't use validates_presence_of boolean attributes because checks attribute present calling blank? method. however, false.blank? true, never let save record when attribute false.

you may want note rails console doesn't automatically pick changes make code. need either call reload! or restart console. when using reload!, careful don't have instances of objects created before call reload! hanging around - may referring previous version of class.