GNOME Bugzilla – Bug 540300
[souphttpsrc] souphttpsrc does not seek ahead in http stream
Last modified: 2008-08-02 21:53:51 UTC
Please describe the problem: When seeking ahead in a streaming mp3 over http with souphttpsrc, the song immediately comes to a stop instead of seeking ahead, and reports that it cannot play the file. Debugging log of this: 0:00:17.206289766 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:804:gst_soup_http_src_got_chunk_cb:<souphttpsrc0> got chunk of 4096 bytes 0:00:17.269479990 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1070:gst_soup_http_src_unlock:<souphttpsrc0> unlock() 0:00:17.269771996 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1085:gst_soup_http_src_unlock_stop:<souphttpsrc0> unlock_stop() 0:00:17.269989971 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1121:gst_soup_http_src_do_seek:<souphttpsrc0> do_seek(24864) 0:00:17.271205209 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1070:gst_soup_http_src_unlock:<souphttpsrc0> unlock() 0:00:17.271390987 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1085:gst_soup_http_src_unlock_stop:<souphttpsrc0> unlock_stop() 0:00:17.271539539 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1121:gst_soup_http_src_do_seek:<souphttpsrc0> do_seek(93312) 0:00:17.273910371 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:764:gst_soup_http_src_chunk_allocator:<souphttpsrc0> alloc 4096 bytes <= 5491594 0:00:17.274174092 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:804:gst_soup_http_src_got_chunk_cb:<souphttpsrc0> got chunk of 4096 bytes 0:00:17.277144162 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1070:gst_soup_http_src_unlock:<souphttpsrc0> unlock() 0:00:17.277383229 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1085:gst_soup_http_src_unlock_stop:<souphttpsrc0> unlock_stop() 0:00:17.277567749 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1121:gst_soup_http_src_do_seek:<souphttpsrc0> do_seek(138944) 0:00:17.281744328 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:764:gst_soup_http_src_chunk_allocator:<souphttpsrc0> alloc 4096 bytes <= 5487498 0:00:17.282059102 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:804:gst_soup_http_src_got_chunk_cb:<souphttpsrc0> got chunk of 4096 bytes 0:00:17.285654322 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:764:gst_soup_http_src_chunk_allocator:<souphttpsrc0> alloc 4096 bytes <= 5483402 0:00:17.286480893 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:804:gst_soup_http_src_got_chunk_cb:<souphttpsrc0> got chunk of 4096 bytes 0:00:17.331547305 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1070:gst_soup_http_src_unlock:<souphttpsrc0> unlock() 0:00:17.331608417 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1085:gst_soup_http_src_unlock_stop:<souphttpsrc0> unlock_stop() 0:00:17.331635864 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1121:gst_soup_http_src_do_seek:<souphttpsrc0> do_seek(321456) 0:00:17.332419344 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1070:gst_soup_http_src_unlock:<souphttpsrc0> unlock() 0:00:17.332602747 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:696:gst_soup_http_src_finished_cb:<souphttpsrc0> finished 0:00:17.332639414 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:843:gst_soup_http_src_response_cb:<souphttpsrc0> got response 1: Cancelled 0:00:17.332717356 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1085:gst_soup_http_src_unlock_stop:<souphttpsrc0> unlock_stop() 0:00:17.332777210 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1121:gst_soup_http_src_do_seek:<souphttpsrc0> do_seek(777760) 0:00:17.335225147 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:972:gst_soup_http_src_create:<souphttpsrc0> Reconnecting 0:00:17.335309725 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:985:gst_soup_http_src_create:<souphttpsrc0> Queueing connection request 0:00:17.336278843 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1070:gst_soup_http_src_unlock:<souphttpsrc0> unlock() 0:00:17.336348544 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:696:gst_soup_http_src_finished_cb:<souphttpsrc0> finished 0:00:17.336375852 3069 0x93d27b0 WARN souphttpsrc gstsouphttpsrc.c:708:gst_soup_http_src_finished_cb:<souphttpsrc0> error: Cancelled 0:00:17.336397503 3069 0x93d27b0 WARN souphttpsrc gstsouphttpsrc.c:708:gst_soup_http_src_finished_cb:<souphttpsrc0> error: libsoup status code 1 0:00:17.336496608 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:843:gst_soup_http_src_response_cb:<souphttpsrc0> got response 1: Cancelled 0:00:17.336558976 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1085:gst_soup_http_src_unlock_stop:<souphttpsrc0> unlock_stop() 0:00:17.336598506 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1121:gst_soup_http_src_do_seek:<souphttpsrc0> do_seek(914640) 0:00:17.339719992 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1070:gst_soup_http_src_unlock:<souphttpsrc0> unlock() 0:00:17.340002221 3069 0x93d27b0 DEBUG souphttpsrc gstsouphttpsrc.c:696:gst_soup_http_src_finished_cb:<souphttpsrc0> finished 0:00:17.340166697 3069 0x93d27b0 WARN souphttpsrc gstsouphttpsrc.c:708:gst_soup_http_src_finished_cb:<souphttpsrc0> error: Cancelled 0:00:17.340316507 3069 0x93d27b0 WARN souphttpsrc gstsouphttpsrc.c:708:gst_soup_http_src_finished_cb:<souphttpsrc0> error: libsoup status code 1 0:00:17.340494951 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1085:gst_soup_http_src_unlock_stop:<souphttpsrc0> unlock_stop() 0:00:17.340672976 3069 0x80687b0 DEBUG souphttpsrc gstsouphttpsrc.c:1051:gst_soup_http_src_stop:<souphttpsrc0> stop() However, if I change line 951 from: if (src->session_io_status == GST_SOUP_HTTP_SRC_SESSION_IO_STATUS_IDLE) { to: if (TRUE) { seeking works *if I do not seek ahead too quickly*. Somewhere along the way src->session_io_status is not being put in the correct state. Or, src->session_io_status is not an proper way of deciding. Steps to reproduce: Actual results: Expected results: Does this happen every time? Other information:
Created attachment 114797 [details] [review] Fix seek. Thanks for reporting this. I found a second bug while fixing this too.
Marking as blocker for the good release on Wouter's behalf.
The patch is small. It fixes two bugs: - seek operation leaks a connection request and starts a duplicate connection request, - unlock() causes a disconnect. The latter breaks seeking. If there's a nice unlock, return from create in streaming thread, unlock_stop, do_seek, create in streaming thread sequence, the seeking logic probably works. However, unlock_stop arrives at any time, wreaking havoc; in the case of this user, there were 6 seek operations in 136 milliseconds. It used to work; if it doesn't any more, then I suspect something in the logic (perhaps due to queue2?) has changed the timing.
Not sure what you mean by "However, unlock_stop arrives at any time" -> it should always be called after unlock, after the streaming thread returns, and before do_seek is called. The patch looks fine in any case.
Committed
you may have fixed another problem, but the seeking problem still exists...
more logging: 0:00:10.792665687 26794 0x80637f0 DEBUG souphttpsrc gstsouphttpsrc.c:1122:gst_soup_http_src_do_seek:<souphttpsrc0> do_seek(70496) 0:00:10.792717719 26794 0x80637f0 LOG GST_PADS gstpad.c:4129:gst_pad_push_event:<souphttpsrc0:src> event: flush-stop 0:00:10.792739649 26794 0x80637f0 LOG GST_PADS gstpad.c:4181:gst_pad_push_event:<souphttpsrc0:src> sending event flush-stop to peerpad <decodebin0:sink> 0:00:10.805852978 26794 0x80637f0 LOG GST_PADS gstpad.c:4189:gst_pad_push_event:<souphttpsrc0:src> sent event to peerpad <decodebin0:sink>, result 1 0:00:10.805901657 26794 0x80637f0 DEBUG basesrc gstbasesrc.c:1240:gst_base_src_perform_seek:<souphttpsrc0> Sending newsegment from 70496 to 5614532 0:00:10.805993428 26794 0x80637f0 DEBUG GST_PADS gstpad.c:4433:gst_pad_start_task:<souphttpsrc0:src> start task 0:00:10.806110901 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:353:gst_object_unref:<souphttpsrc0> 0x8c3e020 unref 2->1 0:00:10.806134019 26794 0x80637f0 DEBUG GST_PADS gstpad.c:4334:gst_pad_send_event:<souphttpsrc0:src> sent event, result 1 0:00:10.806156019 26794 0x80637f0 LOG GST_PADS gstpad.c:4189:gst_pad_push_event:<decodebin0:sink> sent event to peerpad <souphttpsrc0:src>, result 1 0:00:10.806181651 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:353:gst_object_unref:<souphttpsrc0:src> 0x81f2420 unref 3->2 0:00:10.808015892 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0> 0x8c3e020 ref 1->2 0:00:10.808051022 26794 0x80637f0 DEBUG GST_STATES gstbin.c:1418:bin_element_is_sink:<pipeline0> child souphttpsrc0 is not sink 0:00:10.808073511 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:353:gst_object_unref:<souphttpsrc0> 0x8c3e020 unref 2->1 0:00:10.809452807 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0> 0x8c3e020 ref 1->2 0:00:10.809475086 26794 0x80637f0 DEBUG GST_STATES gstbin.c:1418:bin_element_is_sink:<pipeline0> child souphttpsrc0 is not sink 0:00:10.809497086 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:353:gst_object_unref:<souphttpsrc0> 0x8c3e020 unref 2->1 0:00:10.812758045 26794 0x80637f0 LOG GST_PADS gstpad.c:4181:gst_pad_push_event:<decodebin0:sink> sending event seek to peerpad <souphttpsrc0:src> 0:00:10.812782420 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0:src> 0x81f2420 ref 2->3 0:00:10.812804699 26794 0x80637f0 DEBUG GST_EVENT gstpad.c:4306:gst_pad_send_event:<souphttpsrc0:src> have event type seek 0:00:10.812827817 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0> 0x8c3e020 ref 1->2 0:00:10.812958699 26794 0x80637f0 DEBUG basesrc gstbasesrc.c:1114:gst_base_src_perform_seek:<souphttpsrc0> doing seek 0:00:10.813010591 26794 0x80637f0 LOG GST_PADS gstpad.c:4129:gst_pad_push_event:<souphttpsrc0:src> event: flush-start 0:00:10.813032451 26794 0x80637f0 LOG GST_PADS gstpad.c:4181:gst_pad_push_event:<souphttpsrc0:src> sending event flush-start to peerpad <decodebin0:sink> 0:00:10.816198496 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:1770:gst_base_src_update_length:<souphttpsrc0> reading offset 70496, length 4096, size 5614532, segment.stop -1, maxsize 5614532 0:00:10.816231811 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:1858:gst_base_src_get_range:<souphttpsrc0> calling create offset 70496 length 4096, time 70496 0:00:10.816259328 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:957:gst_soup_http_src_create:<souphttpsrc0> Seek from position 76209 to 70496: requeueing connection request 0:00:10.817614109 26794 0x80637f0 LOG GST_PADS gstpad.c:4189:gst_pad_push_event:<souphttpsrc0:src> sent event to peerpad <decodebin0:sink>, result 1 0:00:10.817662509 26794 0x80637f0 DEBUG souphttpsrc gstsouphttpsrc.c:1071:gst_soup_http_src_unlock:<souphttpsrc0> unlock() 0:00:10.817719430 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:696:gst_soup_http_src_finished_cb:<souphttpsrc0> finished 0:00:10.817750370 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:843:gst_soup_http_src_response_cb:<souphttpsrc0> got response 1: Cancelled 0:00:10.817890890 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:969:gst_soup_http_src_create:<souphttpsrc0> interrupted 0:00:10.817919176 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:1934:gst_base_src_get_range:<souphttpsrc0> create returned -3 (unexpected) 0:00:10.817942573 26794 0x9b0c788 INFO basesrc gstbasesrc.c:2103:gst_base_src_loop:<souphttpsrc0> pausing after gst_base_src_get_range() = unexpected 0:00:10.817981335 26794 0x80637f0 DEBUG souphttpsrc gstsouphttpsrc.c:1086:gst_soup_http_src_unlock_stop:<souphttpsrc0> unlock_stop() 0:00:10.818007735 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:2221:gst_base_src_loop:<souphttpsrc0> pausing task, reason unexpected 0:00:10.818030433 26794 0x9b0c788 DEBUG GST_PADS gstpad.c:4467:gst_pad_pause_task:<souphttpsrc0:src> pause task 0:00:10.818111519 26794 0x9b0c788 LOG GST_PADS gstpad.c:4129:gst_pad_push_event:<souphttpsrc0:src> event: eos 0:00:10.818133309 26794 0x9b0c788 LOG GST_PADS gstpad.c:4181:gst_pad_push_event:<souphttpsrc0:src> sending event eos to peerpad <decodebin0:sink> 0:00:10.818335639 26794 0x9b0c788 LOG GST_PADS gstpad.c:4189:gst_pad_push_event:<souphttpsrc0:src> sent event to peerpad <decodebin0:sink>, result 0 0:00:10.818390325 26794 0x80637f0 DEBUG basesrc gstbasesrc.c:1189:gst_base_src_perform_seek:<souphttpsrc0> segment configured from 846208 to -1, position 846208 0:00:10.818415608 26794 0x80637f0 DEBUG souphttpsrc gstsouphttpsrc.c:1122:gst_soup_http_src_do_seek:<souphttpsrc0> do_seek(846208) 0:00:10.818461424 26794 0x80637f0 LOG GST_PADS gstpad.c:4129:gst_pad_push_event:<souphttpsrc0:src> event: flush-stop 0:00:10.818483214 26794 0x80637f0 LOG GST_PADS gstpad.c:4181:gst_pad_push_event:<souphttpsrc0:src> sending event flush-stop to peerpad <decodebin0:sink> 0:00:10.822432459 26794 0x80637f0 LOG GST_PADS gstpad.c:4189:gst_pad_push_event:<souphttpsrc0:src> sent event to peerpad <decodebin0:sink>, result 1 0:00:10.822479742 26794 0x80637f0 DEBUG basesrc gstbasesrc.c:1240:gst_base_src_perform_seek:<souphttpsrc0> Sending newsegment from 846208 to 5614532 0:00:10.822616840 26794 0x80637f0 DEBUG GST_PADS gstpad.c:4433:gst_pad_start_task:<souphttpsrc0:src> start task 0:00:10.822748281 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:353:gst_object_unref:<souphttpsrc0> 0x8c3e020 unref 2->1 0:00:10.822770770 26794 0x80637f0 DEBUG GST_PADS gstpad.c:4334:gst_pad_send_event:<souphttpsrc0:src> sent event, result 1 0:00:10.822792700 26794 0x80637f0 LOG GST_PADS gstpad.c:4189:gst_pad_push_event:<decodebin0:sink> sent event to peerpad <souphttpsrc0:src>, result 1 0:00:10.822819031 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:353:gst_object_unref:<souphttpsrc0:src> 0x81f2420 unref 3->2 0:00:10.824763621 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0> 0x8c3e020 ref 1->2 0:00:10.824786250 26794 0x80637f0 DEBUG GST_STATES gstbin.c:1418:bin_element_is_sink:<pipeline0> child souphttpsrc0 is not sink 0:00:10.824808878 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:353:gst_object_unref:<souphttpsrc0> 0x8c3e020 unref 2->1 0:00:10.826162472 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0> 0x8c3e020 ref 1->2 0:00:10.826184752 26794 0x80637f0 DEBUG GST_STATES gstbin.c:1418:bin_element_is_sink:<pipeline0> child souphttpsrc0 is not sink 0:00:10.826206821 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:353:gst_object_unref:<souphttpsrc0> 0x8c3e020 unref 2->1 0:00:10.827453069 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:1770:gst_base_src_update_length:<souphttpsrc0> reading offset 846208, length 4096, size 5614532, segment.stop -1, maxsize 5614532 0:00:10.827493507 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:1858:gst_base_src_get_range:<souphttpsrc0> calling create offset 846208 length 4096, time 846208 0:00:10.827527310 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:986:gst_soup_http_src_create:<souphttpsrc0> Queueing connection request 0:00:10.831002193 26794 0x80637f0 LOG GST_PADS gstpad.c:4181:gst_pad_push_event:<decodebin0:sink> sending event seek to peerpad <souphttpsrc0:src> 0:00:10.831027127 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0:src> 0x81f2420 ref 2->3 0:00:10.831049755 26794 0x80637f0 DEBUG GST_EVENT gstpad.c:4306:gst_pad_send_event:<souphttpsrc0:src> have event type seek 0:00:10.831072314 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0> 0x8c3e020 ref 1->2 0:00:10.831095292 26794 0x80637f0 DEBUG basesrc gstbasesrc.c:1114:gst_base_src_perform_seek:<souphttpsrc0> doing seek 0:00:10.831144111 26794 0x80637f0 LOG GST_PADS gstpad.c:4129:gst_pad_push_event:<souphttpsrc0:src> event: flush-start 0:00:10.831165482 26794 0x80637f0 LOG GST_PADS gstpad.c:4181:gst_pad_push_event:<souphttpsrc0:src> sending event flush-start to peerpad <decodebin0:sink> 0:00:10.835716410 26794 0x80637f0 LOG GST_PADS gstpad.c:4189:gst_pad_push_event:<souphttpsrc0:src> sent event to peerpad <decodebin0:sink>, result 1 0:00:10.835765369 26794 0x80637f0 DEBUG souphttpsrc gstsouphttpsrc.c:1071:gst_soup_http_src_unlock:<souphttpsrc0> unlock() 0:00:10.835800988 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:969:gst_soup_http_src_create:<souphttpsrc0> interrupted 0:00:10.835823896 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:1934:gst_base_src_get_range:<souphttpsrc0> create returned -3 (unexpected) 0:00:10.835846873 26794 0x9b0c788 INFO basesrc gstbasesrc.c:2103:gst_base_src_loop:<souphttpsrc0> pausing after gst_base_src_get_range() = unexpected 0:00:10.835871039 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:2221:gst_base_src_loop:<souphttpsrc0> pausing task, reason unexpected 0:00:10.835893318 26794 0x9b0c788 DEBUG GST_PADS gstpad.c:4467:gst_pad_pause_task:<souphttpsrc0:src> pause task 0:00:10.835960226 26794 0x9b0c788 LOG GST_PADS gstpad.c:4129:gst_pad_push_event:<souphttpsrc0:src> event: eos 0:00:10.835981527 26794 0x9b0c788 LOG GST_PADS gstpad.c:4181:gst_pad_push_event:<souphttpsrc0:src> sending event eos to peerpad <decodebin0:sink> 0:00:10.836275420 26794 0x9b0c788 LOG GST_PADS gstpad.c:4189:gst_pad_push_event:<souphttpsrc0:src> sent event to peerpad <decodebin0:sink>, result 0 0:00:10.836094810 26794 0x80637f0 DEBUG souphttpsrc gstsouphttpsrc.c:1086:gst_soup_http_src_unlock_stop:<souphttpsrc0> unlock_stop() 0:00:10.836346588 26794 0x80637f0 DEBUG basesrc gstbasesrc.c:1189:gst_base_src_perform_seek:<souphttpsrc0> segment configured from 1348128 to -1, position 1348128 0:00:10.836372499 26794 0x80637f0 DEBUG souphttpsrc gstsouphttpsrc.c:1122:gst_soup_http_src_do_seek:<souphttpsrc0> do_seek(1348128) 0:00:10.836418454 26794 0x80637f0 LOG GST_PADS gstpad.c:4129:gst_pad_push_event:<souphttpsrc0:src> event: flush-stop 0:00:10.836440175 26794 0x80637f0 LOG GST_PADS gstpad.c:4181:gst_pad_push_event:<souphttpsrc0:src> sending event flush-stop to peerpad <decodebin0:sink> 0:00:10.840551661 26794 0x80637f0 LOG GST_PADS gstpad.c:4189:gst_pad_push_event:<souphttpsrc0:src> sent event to peerpad <decodebin0:sink>, result 1 0:00:10.840599642 26794 0x80637f0 DEBUG basesrc gstbasesrc.c:1240:gst_base_src_perform_seek:<souphttpsrc0> Sending newsegment from 1348128 to 5614532 0:00:10.840733598 26794 0x80637f0 DEBUG GST_PADS gstpad.c:4433:gst_pad_start_task:<souphttpsrc0:src> start task 0:00:10.840847788 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:353:gst_object_unref:<souphttpsrc0> 0x8c3e020 unref 2->1 0:00:10.840869998 26794 0x80637f0 DEBUG GST_PADS gstpad.c:4334:gst_pad_send_event:<souphttpsrc0:src> sent event, result 1 0:00:10.840891858 26794 0x80637f0 LOG GST_PADS gstpad.c:4189:gst_pad_push_event:<decodebin0:sink> sent event to peerpad <souphttpsrc0:src>, result 1 0:00:10.840917280 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:353:gst_object_unref:<souphttpsrc0:src> 0x81f2420 unref 3->2 0:00:10.842748868 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0> 0x8c3e020 ref 1->2 0:00:10.842770868 26794 0x80637f0 DEBUG GST_STATES gstbin.c:1418:bin_element_is_sink:<pipeline0> child souphttpsrc0 is not sink 0:00:10.842793427 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:353:gst_object_unref:<souphttpsrc0> 0x8c3e020 unref 2->1 0:00:10.844162036 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0> 0x8c3e020 ref 1->2 0:00:10.844183897 26794 0x80637f0 DEBUG GST_STATES gstbin.c:1418:bin_element_is_sink:<pipeline0> child souphttpsrc0 is not sink 0:00:10.844205967 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:353:gst_object_unref:<souphttpsrc0> 0x8c3e020 unref 2->1 0:00:10.844418144 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:1770:gst_base_src_update_length:<souphttpsrc0> reading offset 1348128, length 4096, size 5614532, segment.stop -1, maxsize 5614532 0:00:10.844447129 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:1858:gst_base_src_get_range:<souphttpsrc0> calling create offset 1348128 length 4096, time 1348128 0:00:10.844472062 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:957:gst_soup_http_src_create:<souphttpsrc0> Seek from position 846208 to 1348128: requeueing connection request 0:00:10.844523395 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:696:gst_soup_http_src_finished_cb:<souphttpsrc0> finished 0:00:10.844549027 26794 0x9b0c788 WARN souphttpsrc gstsouphttpsrc.c:708:gst_soup_http_src_finished_cb:<souphttpsrc0> error: Cancelled 0:00:10.844570468 26794 0x9b0c788 WARN souphttpsrc gstsouphttpsrc.c:708:gst_soup_http_src_finished_cb:<souphttpsrc0> error: libsoup status code 1 0:00:10.844594633 26794 0x9b0c788 DEBUG default gstelement.c:1646:gst_element_message_full:<souphttpsrc0> start 0:00:10.844629135 26794 0x9b0c788 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0> 0x8c3e020 ref 1->2 0:00:10.844703376 26794 0x9b0c788 LOG GST_REFCOUNTING gstobject.c:353:gst_object_unref:<souphttpsrc0> 0x8c3e020 unref 2->1 0:00:10.844730475 26794 0x9b0c788 INFO GST_ERROR_SYSTEM gstelement.c:1677:gst_element_message_full:<souphttpsrc0> posting message: Cancelled 0:00:10.844790887 26794 0x9b0c788 LOG GST_MESSAGE gstmessage.c:289:gst_message_new_custom: source souphttpsrc0: creating new message 0x93fa858 error 0:00:10.844814354 26794 0x9b0c788 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0> 0x8c3e020 ref 1->2 0:00:10.844872881 26794 0x9b0c788 DEBUG GST_BUS gstbus.c:337:gst_bus_post:<bus0> [msg 0x93fa858] posting on bus, type error, GstMessageError, gerror=(GstGError)(NULL), debug=(string)"gstsouphttpsrc.c\(708\):\ gst_soup_http_src_finished_cb\ \(\):\ /pipeline0/souphttpsrc0:\012libsoup\ status\ code\ 1"; from source <souphttpsrc0> 0:00:10.844925052 26794 0x9b0c788 DEBUG bin gstbin.c:2715:gst_bin_handle_message_func:<pipeline0> [msg 0x93fa858] handling child souphttpsrc0 message of type error 0:00:10.844993287 26794 0x9b0c788 DEBUG GST_BUS gstbus.c:337:gst_bus_post:<bus1> [msg 0x93fa858] posting on bus, type error, GstMessageError, gerror=(GstGError)(NULL), debug=(string)"gstsouphttpsrc.c\(708\):\ gst_soup_http_src_finished_cb\ \(\):\ /pipeline0/souphttpsrc0:\012libsoup\ status\ code\ 1"; from source <souphttpsrc0> 0:00:10.845142608 26794 0x9b0c788 INFO GST_ERROR_SYSTEM gstelement.c:1700:gst_element_message_full:<souphttpsrc0> posted error message: Cancelled 0:00:10.845177948 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:843:gst_soup_http_src_response_cb:<souphttpsrc0> got response 1: Cancelled 0:00:10.845295002 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:986:gst_soup_http_src_create:<souphttpsrc0> Queueing connection request 0:00:10.848500856 26794 0x80637f0 LOG GST_PADS gstpad.c:4181:gst_pad_push_event:<decodebin0:sink> sending event seek to peerpad <souphttpsrc0:src> 0:00:10.848632227 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0:src> 0x81f2420 ref 2->3 0:00:10.848658558 26794 0x80637f0 DEBUG GST_EVENT gstpad.c:4306:gst_pad_send_event:<souphttpsrc0:src> have event type seek 0:00:10.848681954 26794 0x80637f0 LOG GST_REFCOUNTING gstobject.c:326:gst_object_ref:<souphttpsrc0> 0x8c3e020 ref 2->3 0:00:10.848705281 26794 0x80637f0 DEBUG basesrc gstbasesrc.c:1114:gst_base_src_perform_seek:<souphttpsrc0> doing seek 0:00:10.848755497 26794 0x80637f0 LOG GST_PADS gstpad.c:4129:gst_pad_push_event:<souphttpsrc0:src> event: flush-start 0:00:10.848777288 26794 0x80637f0 LOG GST_PADS gstpad.c:4181:gst_pad_push_event:<souphttpsrc0:src> sending event flush-start to peerpad <decodebin0:sink> 0:00:10.853344838 26794 0x80637f0 LOG GST_PADS gstpad.c:4189:gst_pad_push_event:<souphttpsrc0:src> sent event to peerpad <decodebin0:sink>, result 1 0:00:10.853393307 26794 0x80637f0 DEBUG souphttpsrc gstsouphttpsrc.c:1071:gst_soup_http_src_unlock:<souphttpsrc0> unlock() 0:00:10.853431231 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:969:gst_soup_http_src_create:<souphttpsrc0> interrupted 0:00:10.853454838 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:1934:gst_base_src_get_range:<souphttpsrc0> create returned -3 (unexpected) 0:00:10.853477466 26794 0x9b0c788 INFO basesrc gstbasesrc.c:2103:gst_base_src_loop:<souphttpsrc0> pausing after gst_base_src_get_range() = unexpected 0:00:10.853500165 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:2221:gst_base_src_loop:<souphttpsrc0> pausing task, reason unexpected 0:00:10.853522095 26794 0x9b0c788 DEBUG GST_PADS gstpad.c:4467:gst_pad_pause_task:<souphttpsrc0:src> pause task 0:00:10.853589422 26794 0x9b0c788 LOG GST_PADS gstpad.c:4129:gst_pad_push_event:<souphttpsrc0:src> event: eos 0:00:10.853610584 26794 0x9b0c788 LOG GST_PADS gstpad.c:4181:gst_pad_push_event:<souphttpsrc0:src> sending event eos to peerpad <decodebin0:sink> 0:00:10.853822622 26794 0x9b0c788 LOG GST_PADS gstpad.c:4189:gst_pad_push_event:<souphttpsrc0:src> sent event to peerpad <decodebin0:sink>, result 0 0:00:10.853873466 26794 0x80637f0 DEBUG souphttpsrc gstsouphttpsrc.c:1086:gst_soup_http_src_unlock_stop:<souphttpsrc0> unlock_stop() 0:00:10.853898819 26794 0x80637f0 DEBUG basesrc gstbasesrc.c:1189:gst_base_src_perform_seek:<souphttpsrc0> segment configured from 1462208 to -1, position 1462208 0:00:10.853922984 26794 0x80637f0 DEBUG souphttpsrc gstsouphttpsrc.c:1122:gst_soup_http_src_do_seek:<souphttpsrc0> do_seek(1462208) 0:00:10.853968171 26794 0x80637f0 LOG GST_PADS gstpad.c:4129:gst_pad_push_event:<souphttpsrc0:src> event: flush-stop 0:00:10.853989682 26794 0x80637f0 LOG GST_PADS gstpad.c:4181:gst_pad_push_event:<souphttpsrc0:src> sending event flush-stop to peerpad <decodebin0:sink> 0:00:10.857957435 26794 0x80637f0 LOG GST_PADS gstpad.c:4189:gst_pad_push_event:<souphttpsrc0:src> sent event to peerpad <decodebin0:sink>, result 1 0:00:10.858005276 26794 0x80637f0 DEBUG basesrc gstbasesrc.c:1240:gst_base_src_perform_seek:<souphttpsrc0> Sending newsegment from 1462208 to 5614532 0:00:10.858133924 26794 0x80637f0 DEBUG GST_PADS gstpad.c:4433:gst_pad_start_task:<souphttpsrc0:src> start task 0:00:10.858190286 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:1770:gst_base_src_update_length:<souphttpsrc0> reading offset 1462208, length 4096, size 5614532, segment.stop -1, maxsize 5614532 0:00:10.858216826 26794 0x9b0c788 DEBUG basesrc gstbasesrc.c:1858:gst_base_src_get_range:<souphttpsrc0> calling create offset 1462208 length 4096, time 1462208 0:00:10.858240921 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:957:gst_soup_http_src_create:<souphttpsrc0> Seek from position 1348128 to 1462208: requeueing connection request 0:00:10.858286597 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:696:gst_soup_http_src_finished_cb:<souphttpsrc0> finished 0:00:10.858329060 26794 0x9b0c788 WARN souphttpsrc gstsouphttpsrc.c:708:gst_soup_http_src_finished_cb:<souphttpsrc0> error: Cancelled 0:00:10.858351340 26794 0x9b0c788 WARN souphttpsrc gstsouphttpsrc.c:708:gst_soup_http_src_finished_cb:<souphttpsrc0> error: libsoup status code 1
The problem looks to be around here: gstsouphttpsrc.c:957:gst_soup_http_src_create:<souphttpsrc0> Seek from position 846208 to 1348128: requeueing connection request 0:00:10.844523395 26794 0x9b0c788 DEBUG souphttpsrc gstsouphttpsrc.c:696:gst_soup_http_src_finished_cb:<souphttpsrc0> finished 0:00:10.844549027 26794 0x9b0c788 WARN souphttpsrc gstsouphttpsrc.c:708:gst_soup_http_src_finished_cb:<souphttpsrc0> error: Cancelled 0:00:10.844570468 26794 0x9b0c788 WARN souphttpsrc gstsouphttpsrc.c:708:gst_soup_http_src_finished_cb:<souphttpsrc0> error: libsoup status code 1 Where it then posts an error on the bus for what looks like an error that should be being ignored. I don't know if this is actually a blocker for the 0.10.9 release (which is supposed to happen tonight) - is it a regression from 0.10.8?
Created attachment 115643 [details] [review] Don't send an error on the bus for an operation that was cancelled due to seeking
Attached patch fixes it for me. I'm tempted to just commit it and release without another pre-release cycle, what do others think?
Looks good to me, and if it doesn't work, this isn't a regression from the previous release (where seeking didn't work anyway), so I don't see a need for another prerel.
* ext/soup/gstsouphttpsrc.c: Don't throw an error when soup completes a msg with status 'cancelled', as that indicates we cancelled a request while shutting down or seeking, and it's not an error. Fixes: #540300 again.
This doesn't make any sense. In the case of a seek, the status should be GST_SOUP_HTTP_SRC_SESSION_IO_STATUS_RUNNING, and then the error will not occur. Has anyone besides the poster of this bug been able to reproduce this behaviour? This certainly didn't happen when I tried this with Totem. I strongly suspect that the patch simply ignores a symptom. Jason, could you provide a detailed description of how you triggered this problem? What are you using to seek exactly? Does this happen systematically with every combination of MP3 file and web server, or is this one specific setup?
I was able to reproduce it fairly easily, using the 'seek' example in gst-plugins-base/test/examples/seek ./seek 15 "souphttpsrc location=http://.../foo.mp3 ! decodebin ! audioconvert ! alsasink" and then seeking around a bit. The error wasn't emitted every time, but somewhere around 8/10 times, it'd trigger it. That suggests that it's something to do with the precise timing of the cancellation to me. The server was a bog standard apache hosting an mp3 file.
Created attachment 115712 [details] [review] Fix behaviour when seeking extremly rapidly and fix libsoup assert. Cool, somebody wrote a seek test program. The seek test was pretty broken when I wrote souphttpsrc. I understand the behaviour now. The case is indeed caused by timing; a new seek that cancels the HTTP request before connection setup is complete will cause it. The seek program exhibits that nasty behaviour by triggering seeks while dragging the position scroll bar. The patch in attachment 115643 [details] [review] probably covers all cases. I'm attaching a patch that exposes this case more visibly through a new 'cancelled' state, active only when the connection is being torn down, which actually only happens as a result of a seek. The seek program also triggers an assert by libsoup in some cases, that the SoupMessage we use is not a valid SoupMessage. This is caused by attempting to cancel a SoupMessage whose lifecycle had already ended, so it's a bug. Removing our pointer to it in gst_soup_http_src_response_cb() fixes that.
has that been committed?
Jan Schmidt's patch; yes. My patch, no. I'm not a committer.
gst-plugins-good 0.10.9 was released with my patch, which seems to work OK. Patch in attachment 115643 [details] [review] committed. 2008-08-02 Jan Schmidt <jan.schmidt@sun.com> * ext/soup/gstsouphttpsrc.c: * ext/soup/gstsouphttpsrc.h: Fix seeking race condition in #540300 Patch By: Wouter Cloetens <wouter at mind be> Doing some more testing with the seek example, it looks like there is a problem with segment seeks (turning on the Loop toggle) - it will occasionally deadlock while seeking, but U'm not sure why. Doesn't happen with (for e.g.) gnomevfssrc.
+ Trace 204448
Thread 1 (Thread 0xb725b720 (LWP 28204))