manual import of hashes fails (again?)

nodiscc commented 4 months ago

Have you checked the roadmap on the website, and existing issues, before opening a dupllcate issue? Yes

Describe the bug

I'm trying to import a torrent manually by POSTing JSON to the /import endpoint. Even though bitmagnet returns HTTP 200/success message 1 items imported, nothing gets imported (no items on web interface, no items in database)

This is the same symptom as https://github.com/bitmagnet-io/bitmagnet/issues/10

To Reproduce Steps to reproduce the behavior:

Get information from a .torrent file using transmission-show or similar
Create demo.json

{"infoHash":"0000000011111112222222333334444445555666","name":"ASTRONEER.v0.2.89.0.rar","size":546308096,"contentType":"game","publishedAt":"2019-10-11T16:32:58.000Z","source":"torrent"}

POST the json to the /import endpoint

$ cat demo.json | curl --insecure --verbose -H "Content-Type: application/json" --data-binary @- https://bitmagnet.example.org/import
*   Trying 10.0.10.223:443...
* Connected to bitmagnet.example.org (10.0.10.223) port 443 (#0)
* ALPN: offers h2,http/1.1
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=bitmagnet.example.org
*  start date: Feb 15 19:37:56 2024 GMT
*  expire date: Feb 12 19:37:56 2034 GMT
*  issuer: CN=bitmagnet.example.org
*  SSL certificate verify result: self-signed certificate (18), continuing anyway.
* using HTTP/2
* h2h3 [:method: POST]
* h2h3 [:path: /import]
* h2h3 [:scheme: https]
* h2h3 [:authority: bitmagnet.example.org]
* h2h3 [user-agent: curl/7.88.1]
* h2h3 [accept: */*]
* h2h3 [content-type: application/json]
* h2h3 [content-length: 185]
* Using Stream ID: 1 (easy handle 0x55b098feec80)
> POST /import HTTP/2
> Host: bitmagnet.example.org
> user-agent: curl/7.88.1
> accept: */*
> content-type: application/json
> content-length: 185
> 
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* We are completely uploaded and fine
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
< HTTP/2 200 
< x-xss-protection: 1; mode=block
< referrer-policy: same-origin
< x-permitted-cross-domain-policies: none
< x-robots-tag: noindex,nofollow,noarchive,nosnippet
< vary: Origin
< date: Thu, 15 Feb 2024 20:12:48 GMT
< content-length: 17
< content-type: text/plain; charset=utf-8
< server: Apache
< 
1 items imported
* Connection #0 to host bitmagnet.example.org left intact

Open the web interface, no torrents are displayed
Check logs, no error or suspicicious messages even with log.level: debug
Check torrents and queue_jobs database tables, no rows inserted there.

Expected behavior

I expect the torrent to be imported with the request mentioned above, especially if the query returns 1 items imported.

General (please complete the following information):

Bitmagnet version: 0.7.0 (go install)
OS and version: Debian 12 on client and server

Additional context Instance behind apache reverse proxy, self-signed certificate, postgresql 15

mgdigital commented 4 months ago

Hi, do you have the queue worker running? The import requires a queue job process_torrent to run before the torrent will appear in the app. If you open the Prometheus metrics at /metrics and look for metrics starting 'bitmagnet_queue' you should see at least 1 processed job.

There is also query caching in the web app that can be busted by refreshing the round blue refresh button.

Please let me know if this helped!

nodiscc commented 4 months ago

Hi,

do you have the queue worker running?

bitmagnet is running with these options, so I guess I do (i have no use for the dht_crawler for now)

$ ./bin/bitmagnet worker run --keys=queue_server  --keys=http_server
INFO    migrator    migrations/migrator.go:68   checking and applying migrations...
INFO    migrator    migrations/logger.go:33 goose: no migrations to run. current version: 12
WARN    tmdb_client tmdb/factory.go:40  you are using the default TMDB api key; TMDB requests will be limited to 1 per second; to remove this warning please configure a personal TMDB api key
INFO    worker/worker.go:195    started worker  {"key": "queue_server"}
INFO    worker/worker.go:195    started worker  {"key": "http_server"}

$ cat .config/bitmagnet/config.yml 
postgres:
  host: 127.0.0.1
  name: bitmagnet
  password: _________
  port: 5432
  user: bitmagnet
dht_crawler:
  save_files_threshold: 50
  scaling_factor: 10
  save_pieces: false
log:
  level: info
http_server:
  options: ["*"]
  local_address: ":3333"

Prometheus metrics at /metrics and look for metrics starting 'bitmagnet_queue'

No such metric (Ctrl+F queue -> no results)

# HELP bitmagnet_dht_ktable_hashes_added Total number of hashes added to routing table.
# TYPE bitmagnet_dht_ktable_hashes_added counter
bitmagnet_dht_ktable_hashes_added 0
# HELP bitmagnet_dht_ktable_hashes_count Number of hashes in routing table.
# TYPE bitmagnet_dht_ktable_hashes_count gauge
bitmagnet_dht_ktable_hashes_count 0
# HELP bitmagnet_dht_ktable_hashes_dropped Total number of hashes dropped from routing table.
# TYPE bitmagnet_dht_ktable_hashes_dropped counter
bitmagnet_dht_ktable_hashes_dropped 0
# HELP bitmagnet_dht_ktable_nodes_added Total number of nodes added to routing table.
# TYPE bitmagnet_dht_ktable_nodes_added counter
bitmagnet_dht_ktable_nodes_added 0
# HELP bitmagnet_dht_ktable_nodes_count Number of nodes in routing table.
# TYPE bitmagnet_dht_ktable_nodes_count gauge
bitmagnet_dht_ktable_nodes_count 0
# HELP bitmagnet_dht_ktable_nodes_dropped Total number of nodes dropped from routing table.
# TYPE bitmagnet_dht_ktable_nodes_dropped counter
bitmagnet_dht_ktable_nodes_dropped 0
# HELP bitmagnet_meta_info_requester_concurrency Number of concurrent meta info requests.
# TYPE bitmagnet_meta_info_requester_concurrency gauge
bitmagnet_meta_info_requester_concurrency 0
# HELP bitmagnet_meta_info_requester_duration_seconds Duration of successful meta info requests in seconds.
# TYPE bitmagnet_meta_info_requester_duration_seconds histogram
bitmagnet_meta_info_requester_duration_seconds_bucket{le="0.005"} 0
bitmagnet_meta_info_requester_duration_seconds_bucket{le="0.01"} 0
bitmagnet_meta_info_requester_duration_seconds_bucket{le="0.025"} 0
bitmagnet_meta_info_requester_duration_seconds_bucket{le="0.05"} 0
bitmagnet_meta_info_requester_duration_seconds_bucket{le="0.1"} 0
bitmagnet_meta_info_requester_duration_seconds_bucket{le="0.25"} 0
bitmagnet_meta_info_requester_duration_seconds_bucket{le="0.5"} 0
bitmagnet_meta_info_requester_duration_seconds_bucket{le="1"} 0
bitmagnet_meta_info_requester_duration_seconds_bucket{le="2.5"} 0
bitmagnet_meta_info_requester_duration_seconds_bucket{le="5"} 0
bitmagnet_meta_info_requester_duration_seconds_bucket{le="10"} 0
bitmagnet_meta_info_requester_duration_seconds_bucket{le="+Inf"} 0
bitmagnet_meta_info_requester_duration_seconds_sum 0
bitmagnet_meta_info_requester_duration_seconds_count 0
# HELP bitmagnet_meta_info_requester_error_total Total number of failed meta info requests.
# TYPE bitmagnet_meta_info_requester_error_total counter
bitmagnet_meta_info_requester_error_total 0
# HELP bitmagnet_meta_info_requester_success_total Total number of successful meta info requests.
# TYPE bitmagnet_meta_info_requester_success_total counter
bitmagnet_meta_info_requester_success_total 0
# HELP bitmagnet_process_cpu_seconds_total Total user and system CPU time spent in seconds.
# TYPE bitmagnet_process_cpu_seconds_total counter
bitmagnet_process_cpu_seconds_total 2.55
# HELP bitmagnet_process_max_fds Maximum number of open file descriptors.
# TYPE bitmagnet_process_max_fds gauge
bitmagnet_process_max_fds 1.048576e+06
# HELP bitmagnet_process_open_fds Number of open file descriptors.
# TYPE bitmagnet_process_open_fds gauge
bitmagnet_process_open_fds 15
# HELP bitmagnet_process_resident_memory_bytes Resident memory size in bytes.
# TYPE bitmagnet_process_resident_memory_bytes gauge
bitmagnet_process_resident_memory_bytes 4.7607808e+07
# HELP bitmagnet_process_start_time_seconds Start time of the process since unix epoch in seconds.
# TYPE bitmagnet_process_start_time_seconds gauge
bitmagnet_process_start_time_seconds 1.70803358394e+09
# HELP bitmagnet_process_virtual_memory_bytes Virtual memory size in bytes.
# TYPE bitmagnet_process_virtual_memory_bytes gauge
bitmagnet_process_virtual_memory_bytes 1.293160448e+09
# HELP bitmagnet_process_virtual_memory_max_bytes Maximum amount of virtual memory available in bytes.
# TYPE bitmagnet_process_virtual_memory_max_bytes gauge
bitmagnet_process_virtual_memory_max_bytes 1.8446744073709552e+19
# HELP go_gc_duration_seconds A summary of the pause duration of garbage collection cycles.
# TYPE go_gc_duration_seconds summary
go_gc_duration_seconds{quantile="0"} 4.4093e-05
go_gc_duration_seconds{quantile="0.25"} 6.6235e-05
go_gc_duration_seconds{quantile="0.5"} 7.6203e-05
go_gc_duration_seconds{quantile="0.75"} 0.000112141
go_gc_duration_seconds{quantile="1"} 0.000244087
go_gc_duration_seconds_sum 0.000542759
go_gc_duration_seconds_count 5
# HELP go_goroutines Number of goroutines that currently exist.
# TYPE go_goroutines gauge
go_goroutines 24
# HELP go_info Information about the Go environment.
# TYPE go_info gauge
go_info{version="go1.21.5"} 1
# HELP go_memstats_alloc_bytes Number of bytes allocated and still in use.
# TYPE go_memstats_alloc_bytes gauge
go_memstats_alloc_bytes 9.357624e+06
# HELP go_memstats_alloc_bytes_total Total number of bytes allocated, even if freed.
# TYPE go_memstats_alloc_bytes_total counter
go_memstats_alloc_bytes_total 1.65468e+07
# HELP go_memstats_buck_hash_sys_bytes Number of bytes used by the profiling bucket hash table.
# TYPE go_memstats_buck_hash_sys_bytes gauge
go_memstats_buck_hash_sys_bytes 1.470369e+06
# HELP go_memstats_frees_total Total number of frees.
# TYPE go_memstats_frees_total counter
go_memstats_frees_total 99936
# HELP go_memstats_gc_sys_bytes Number of bytes used for garbage collection system metadata.
# TYPE go_memstats_gc_sys_bytes gauge
go_memstats_gc_sys_bytes 4.499952e+06
# HELP go_memstats_heap_alloc_bytes Number of heap bytes allocated and still in use.
# TYPE go_memstats_heap_alloc_bytes gauge
go_memstats_heap_alloc_bytes 9.357624e+06
# HELP go_memstats_heap_idle_bytes Number of heap bytes waiting to be used.
# TYPE go_memstats_heap_idle_bytes gauge
go_memstats_heap_idle_bytes 3.104768e+06
# HELP go_memstats_heap_inuse_bytes Number of heap bytes that are in use.
# TYPE go_memstats_heap_inuse_bytes gauge
go_memstats_heap_inuse_bytes 1.265664e+07
# HELP go_memstats_heap_objects Number of allocated objects.
# TYPE go_memstats_heap_objects gauge
go_memstats_heap_objects 47180
# HELP go_memstats_heap_released_bytes Number of heap bytes released to OS.
# TYPE go_memstats_heap_released_bytes gauge
go_memstats_heap_released_bytes 2.21184e+06
# HELP go_memstats_heap_sys_bytes Number of heap bytes obtained from system.
# TYPE go_memstats_heap_sys_bytes gauge
go_memstats_heap_sys_bytes 1.5761408e+07
# HELP go_memstats_last_gc_time_seconds Number of seconds since 1970 of last garbage collection.
# TYPE go_memstats_last_gc_time_seconds gauge
go_memstats_last_gc_time_seconds 1.7080336948827546e+09
# HELP go_memstats_lookups_total Total number of pointer lookups.
# TYPE go_memstats_lookups_total counter
go_memstats_lookups_total 0
# HELP go_memstats_mallocs_total Total number of mallocs.
# TYPE go_memstats_mallocs_total counter
go_memstats_mallocs_total 147116
# HELP go_memstats_mcache_inuse_bytes Number of bytes in use by mcache structures.
# TYPE go_memstats_mcache_inuse_bytes gauge
go_memstats_mcache_inuse_bytes 4800
# HELP go_memstats_mcache_sys_bytes Number of bytes used for mcache structures obtained from system.
# TYPE go_memstats_mcache_sys_bytes gauge
go_memstats_mcache_sys_bytes 15600
# HELP go_memstats_mspan_inuse_bytes Number of bytes in use by mspan structures.
# TYPE go_memstats_mspan_inuse_bytes gauge
go_memstats_mspan_inuse_bytes 175224
# HELP go_memstats_mspan_sys_bytes Number of bytes used for mspan structures obtained from system.
# TYPE go_memstats_mspan_sys_bytes gauge
go_memstats_mspan_sys_bytes 179256
# HELP go_memstats_next_gc_bytes Number of heap bytes when next garbage collection will take place.
# TYPE go_memstats_next_gc_bytes gauge
go_memstats_next_gc_bytes 1.6187896e+07
# HELP go_memstats_other_sys_bytes Number of bytes used for other system allocations.
# TYPE go_memstats_other_sys_bytes gauge
go_memstats_other_sys_bytes 1.016399e+06
# HELP go_memstats_stack_inuse_bytes Number of bytes in use by the stack allocator.
# TYPE go_memstats_stack_inuse_bytes gauge
go_memstats_stack_inuse_bytes 1.015808e+06
# HELP go_memstats_stack_sys_bytes Number of bytes obtained from system for stack allocator.
# TYPE go_memstats_stack_sys_bytes gauge
go_memstats_stack_sys_bytes 1.015808e+06
# HELP go_memstats_sys_bytes Number of bytes obtained from system.
# TYPE go_memstats_sys_bytes gauge
go_memstats_sys_bytes 2.3958792e+07
# HELP go_threads Number of OS threads created.
# TYPE go_threads gauge
go_threads 9

query caching in the web app that can be busted by refreshing the round blue refresh button.

Tried it as well, without result

mgdigital commented 4 months ago

Hmm I've just tried importing this JSON snippet, using this command:

cat demo.json | curl --verbose -H "Content-Type: application/json" -H "Connection: close" --data-binary @- http://localhost:3333/import

And it's working for me (see screenshot). If you could open the database could you let me know:

Do you see the imported torrent in the torrents table? Do you see the associated record in the torrent_contents table? (the contents of this table is what's displayed in the UI) Do you see any associated jobs in the queue_jobs table?

The other issue you linked was resolved several months ago, I'm not aware of any issues with the importer at the moment....

mgdigital commented 4 months ago

I think this might be a clue from your output above:

1 items imported
* Connection #0 to host bitmagnet.example.org left intact

When I make the request exactly as in the docs I see:

1 items imported
* Closing connection

The importer is expecting lines of JSON. When the connection closes (or after 100 lines) it will flush the current batch in the import and commit the DB transaction. I suspect the connection didn't close and it's sitting waiting for the next line of JSON.

Can you confirm if the command from my previous comment (with the close header) works? Looks like it might be working but the output can possibly be more helpful in the case of an unclosed connection....

mgdigital commented 4 months ago

@nodiscc , I've been able to replicate the issue whereby leaving the connection unclosed results in items being left unimported. This is fixed in https://github.com/bitmagnet-io/bitmagnet/pull/138

mgdigital commented 4 months ago

The fix for this is now available in https://github.com/bitmagnet-io/bitmagnet/releases/tag/v0.7.1

nodiscc commented 4 months ago

Confirmed fixed! Thanks!

Edit: adding -H "Connection: close" did not fix the problem before the patch, as this header doesn't have any effects on HTTP/2 connections. I tried downgarding to HTTP/1.1 but the problem was still present despite the connection being apparently closed. The patch fixes it regardless of the HTTP version or closed status of the connection.

bitmagnet-io / bitmagnet

manual import of hashes fails (again?) #133